Learn how easy it is to sync an existing GitHub or Google Code repo to a SourceForge project! See Demo

Close

#346 gbrowse 2.16 memory leak

v2.0
open
Lincoln Stein
None
5
2010-12-10
2010-12-01
Anonymous
No

We are running several gbrowse databases through a single apache instance, and have noticed intermittent memory leak issues where gbrowse processes hang and consume large amounts of memory. We have had to resort to Apache::Resource and cron jobs to keep these from bringing down the server.

This is Bio::Graphics 2.15 and GBrowse 2.16.

The last time this situation was witnessed, we noticed several errors in the apache error log as follows:

1) The following four lines would be logged together for one session:
[Tue Nov 30 16:07:28 2010] [error] [client 127.0.0.1] Use of uninitialized value in division (/) at /scratch/gbrowse/custom/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Render.pm line 2652.
[Tue Nov 30 16:07:28 2010] [error] [client 127.0.0.1] Use of uninitialized value in division (/) at /scratch/gbrowse/custom/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Render.pm line 2652.
[Tue Nov 30 16:07:28 2010] [error] [client 127.0.0.1] Use of uninitialized value $start in division (/) at /scratch/gbrowse/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Region.pm line 126.
[Tue Nov 30 16:07:28 2010] [error] [client 127.0.0.1] Use of uninitialized value $stop in division (/) at /scratch/gbrowse/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Region.pm line 126.

2) another example from a different session:
[Tue Nov 30 16:09:10 2010] [error] [client 127.0.0.1] Reverting coordinates to last known good region (user probably hit 'back' button). at /scratch/gbrowse/custom/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Render.pm line 2626., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:10 2010] [error] [client 127.0.0.1] Use of uninitialized value in concatenation (.) or string at /scratch/gbrowse/custom/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Render.pm line 2652., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:10 2010] [error] [client 127.0.0.1] Use of uninitialized value in multiplication (*) at /scratch/gbrowse/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/RenderPanels.pm line 941., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:10 2010] [error] [client 127.0.0.1] Illegal division by zero at /scratch/gbrowse/lib/perl5/Bio/Graphics/Panel.pm line 238., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:10 2010] [error] [client 127.0.0.1] Premature end of script headers: gbrowse, referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268

3) another example for a different session:
[Tue Nov 30 16:09:42 2010] [error] [client 127.0.0.1] Use of uninitialized value in subtraction (-) at /scratch/gbrowse/custom/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Render.pm line 2680., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:42 2010] [error] [client 127.0.0.1] Use of uninitialized value in subtraction (-) at /scratch/gbrowse/custom/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Render.pm line 2680., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:42 2010] [error] [client 127.0.0.1] Use of uninitialized value in addition (+) at /scratch/gbrowse/custom/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Render.pm line 2681., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:42 2010] [error] [client 127.0.0.1] Reverting coordinates to last known good region (user probably hit 'back' button). at /scratch/gbrowse/custom/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Render.pm line 2626., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:42 2010] [error] [client 127.0.0.1] Use of uninitialized value in concatenation (.) or string at /scratch/gbrowse/custom/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/Render.pm line 2652., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:42 2010] [error] [client 127.0.0.1] Use of uninitialized value in multiplication (*) at /scratch/gbrowse/lib/perl5/x86_64-linux-gnu-thread-multi/Bio/Graphics/Browser2/RenderPanels.pm line 941., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:42 2010] [error] [client 127.0.0.1] Illegal division by zero at /scratch/gbrowse/lib/perl5/Bio/Graphics/Panel.pm line 238., referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268
[Tue Nov 30 16:09:42 2010] [error] [client 127.0.0.1] Premature end of script headers: gbrowse, referer: http://www.phytozome.net/cgi-bin/gbrowse/soybean/?enable=UserBlast;ref=Gm07;start=35187123;end=35191268

I managed to track the first set to an issue with Bio::Graphics::Browser2::DataSource->unit_divider not acting as expected and returning a value of 1 if there is no configured parameter for "unit_divider" in the global config file. Instead, calls to $source->unit_divider in Bio::Graphics::Browser2::Render->region_string() receive an undefined value which causes the division error at line 2652.

region_string() and unit_divider() are called throughout the gbrowse codebase. The main culprit must be elsewhere in the code, as the main failure appears to be loss of session/state data

Discussion


  • Anonymous
    2010-12-08

    I have patched a few modules to ensure that unit_divider() calls default to 1 instead of sometimes receiving an empty string. To me, this is an odd bug, as the unit_divider() method itself should be trapping a lack of this param and defaulting to 1 as currently written in Bio::Graphics::Browser2::DataSource

    return $self->global_setting('unit_divider') || 1;

    Otherwise, the other two sets of error messages are still recurring in our installation of GBrowse 2.16. This trend in error logs and runaway processes are related (probably not exclusively) to our site employing links with the "enable" query string parameter to turn on a remote feature to display blast results for users in Gbrowse.

    The following steps do not necessarily produce a runaway gbrowse process, but do highlight a reproducible bug in track display following deferred rendering of both local and remote tracks. From a gene of interest on Phytozome, (e.g. http://www.phytozome.net/genePage.php?search=1&detail=1&crown&method=0&searchText=transcriptid%3A16310443\), select the Sequence tab and click the button requesting blast of the CDS on Phytozome. From the search page, click to select Arabidopsis thaliana as a target and click "submit" in the Blast Search box to run blastn. The HSP glyphs in blast results link to Gbrowse.

    GBrowse display hangs and never displays the enabled UserBlast track or the rest of the requested default local tracks. Sometimes blank tracks display blacHowever, I discovered that if I hit the browser reload button after waiting a sufficient time for all forked render processes to complete according to the apache log, all tracks display correctly from the generated cached images and subsequent navigation around the same datasource organism works fine. So, rendering of both local and remote tracks is successful.

    This is agonizingly not 100% reproducible, and seems to only happen the first time that blast results for a new organism are loaded. Could there be a problem related to gbrowse session management or session file management? If I clear my browser cache, click on File->Reset to reset gbrowse, and access the same blast results, a gbrowse that previously was problematic loads fine.

    I turned on debugging output for Bio::Graphics:: Browser modules Render.pm, Render/HTML.pm, RenderPanels.pm, and RemoteSet.pm on a development server running the same hardware and software versions as the live site. Attached is the debugging output from loading remote blast results gff3 on a datasource that has not been viewed before in the current session. We are quickly running into the max_render_processes limit for forked render processes, since we are requesting five local track and one remote track. The final setting of get_data(1) for all labels at the end of renderPanel::request_panels() (line 1450) is getting lost, and tracks are not displayed, despite successful GD object creation and child process "reaping" in the error logs.

    I noticed that Render::fork() is warning both the child Id for a new forked processed and also "forked 0". I presume this is due to an attempt to fork in fastcgi, which we do not have installed (we are using mod_perl). Could this cause any downstream problems?

    It is hard to tell if any of this is directly leading to orphaned gbrowse processes that consume memory, as I have not been able to force a recreation of that condition in our development environment.

     
    Last edit: Anonymous 2014-04-04

  • Anonymous
    2010-12-08

    Gbrowse error log showing condition of successful deferred rendering when no tracks display in web browser

     

  • Anonymous
    2010-12-08

    Bio::Graphics::Browser2::Render unit_divider simple patch

     

  • Anonymous
    2010-12-08

    Bio::Graphics::Browser2::Render::HTML unit_divider simple patch

     

  • Anonymous
    2010-12-08

    Bio::Graphics::Browser2::RenderPanels unit_divider simple patch

     

  • Anonymous
    2010-12-08

    Bio::Graphics::Browser2::DataSource unit_divider simple patch

     
  • Scott Cain
    Scott Cain
    2010-12-10

    • assigned_to: nobody --> lstein