Skip to content

Large memory footprint in astropy.io.votable.parse_single_table #8946

Closed

Description

@manodeep

I was trying to read two columns from an ~ 1 GB votable file (demo Gaia dr2 data). The file itself contains ~ 96 columns. The code I used was:

from astropy.io.votable import parse_single_table
columns = ['phot_g_mean_mag', 'parallax']
table = parse_single_table("async_20190630210155.vot", columns=columns)
print("Done reading table")

Here's the file info:

$ ls -alh async_20190630210155.vot 
-rw-rw-rw- 1 msinha 1195219923 1.1G Jul  1 14:01 async_20190630210155.vot

Looking at the memory footprint, I saw that python was taking ~12 GB during the read and I cancelled the kernel (this is within a Jupyter notebook). Here's my screenshot showing the memory usage:
Screen Shot 2019-07-02 at 10 13 50 am

While I know that there is a significant python overhead, it still seems like a lot of memory to read only 2 columns (out of 96). By my math, the (minimum) possible size is 2/96*1 GB ~ 0.02 GB

Since I am new to both astropy and votables, perhaps I am doing something incorrectly. Happy to provide further info or help debug, as necessary. In case there is something inherently wrong with the file itself, here's a dropbox link to the file.

Cheers,
Manodeep

Activity

  1. manodeep commented on Jul 3, 2019

    @manodeep
    ContributorAuthor

    I ran the memory profiler within the jupyter notebook (new jupyter session, new browser session) to see what might be going on.

    %load_ext memory_profiler
    
    %%file mprun_demo.py
    def read_votable():
        from astropy.io.votable import parse_single_table
        columns = ['phot_g_mean_mag', 'parallax']
        table = parse_single_table("async_20190630210155.vot", columns=columns)
        print("Done reading table")
        return table.to_table(use_names_over_ids=True)
    
    from mprun_demo import read_votable
    %mprun -f read_votable read_votable()

    The system activity monitor had the memory usage roughly constant at 11.6 GB for the ~20 mins that I let the code run (the read did not complete, that's why the last two lines were not executed). The function memory profile accounts for less than 1 GB.

    Line #    Mem usage    Increment   Line Contents
    ================================================
         1     53.4 MiB     53.4 MiB   def read_votable():
         2     65.6 MiB     12.2 MiB       from astropy.io.votable import parse_single_table
         3     65.6 MiB      0.0 MiB       columns = ['phot_g_mean_mag', 'parallax']
         4    796.5 MiB    730.9 MiB       table = parse_single_table("async_20190630210155.vot", columns=columns)
         5                                 print("Done reading table")
         6                                 return table.to_table(use_names_over_ids=True)

    I am not sure how to include the memory profile for all the called functions, but it seems that the excessive memory is coming from some function within the votable routines.

  2. manodeep commented on Jul 3, 2019

    @manodeep
    ContributorAuthor

    For completeness, here's the output from line_profiler:

    Line #      Hits         Time  Per Hit   % Time  Line Contents
    ==============================================================
         1                                           def read_votable():
         2         1        244.0    244.0      0.0      from astropy.io.votable import parse_single_table
         3         1          4.0      4.0      0.0      columns = ['phot_g_mean_mag', 'parallax']
         4         1  233305074.0 233305074.0    100.0      table = parse_single_table("async_20190630210155.vot", columns=columns)
         5                                               print("Done reading table")
         6                                               return table.to_table(use_names_over_ids=True)

    Nothing surprising. All of the runtime is in the parse_single_table function.

  3. pllim commented on Jul 9, 2019

    @pllim
    Member

    Thanks for reporting this. Sounds like a bug, perhaps due to memory leak. 🤔

    To profile the underlying calls, for the memory part, might need to call them directly, which is not very fun. For the performance part, might have to fall back to cProfile.

    It all starts here:

    def parse_single_table(source, **kwargs):
    """
    Parses a VOTABLE_ xml file (or file-like object), reading and
    returning only the first `~astropy.io.votable.tree.Table`
    instance.
    See `parse` for a description of the keyword arguments.
    Returns
    -------
    votable : `~astropy.io.votable.tree.Table` object
    """
    if kwargs.get('table_number') is None:
    kwargs['table_number'] = 0
    votable = parse(source, **kwargs)
    return votable.get_first_table()

  4. manodeep commented on Jul 9, 2019

    @manodeep
    ContributorAuthor

    Thanks @pllim. Since topcat read in the file just fine, I can confirm that this is indeed a bug within astropy and not something peculiar about the file.

  5. pllim commented on Aug 13, 2019

    @pllim
    Member

    Finally got around to downloading this file. I just fired up volint and immediately I see one of the CPU at 100% capacity (probably expected, though the CPU switches from one to the other once in a while) and memory use quickly ramped up to about over 20 GB and one point (whaaaat?) and then ramp down a bit and is staying much or less around 16-17 GB. 😱 Given how long you reported that it takes to parse the file (20 mins), I am gonna have to kill this job. Something is obviously not right...

    When I kill the job, here is the traceback it spitted out before it died:

      File ".../bin/volint", line 11, in <module>
        load_entry_point('astropy==4.0.dev25415', 'console_scripts', 'volint')()
      File ".../astropy/io/votable/volint.py", line 18, in main
        table.validate(args.filename[0])
      File ".../astropy/io/votable/table.py", line 283, in validate
        votable = parse(content_buffer, verify='warn', filename=filename)
      File ".../astropy/utils/decorators.py", line 521, in wrapper
        return function(*args, **kwargs)
      File ".../astropy/io/votable/table.py", line 167, in parse
        config=config, pos=(1, 1)).parse(iterator, config)
      File ".../astropy/io/votable/tree.py", line 3391, in parse
        iterator, tag, data, config, pos)
      File ".../astropy/io/votable/tree.py", line 3320, in _add_resource
        resource.parse(self, iterator, config)
      File ".../astropy/io/votable/tree.py", line 3142, in parse
        iterator, tag, data, config, pos)
      File ".../astropy/io/votable/tree.py", line 3093, in _add_table
        table.parse(iterator, config)
      File ".../astropy/io/votable/tree.py", line 2396, in parse
        2, iterator, colnumbers, fields, config, pos)
      File ".../astropy/io/votable/tree.py", line 2631, in _parse_binary
        value, value_mask = binparse(careful_read)
      File ".../astropy/io/votable/converters.py", line 649, in binparse
        return result[0], self.is_null(result[0])
    

    This appears to be a BINARY2 format.

    Note to self: What is this undocumented _debug_python_based_parser option in table.py? 🤔

  6. pllim commented on Mar 13, 2020

    @pllim
  7. manodeep commented on Mar 13, 2020

    @manodeep
    ContributorAuthor

    Probably wouldn't be the case in the immigrant library ;-)

  8. pllim commented on Mar 13, 2020

    @pllim
  9. manodeep commented on Mar 13, 2020

    @manodeep
    ContributorAuthor
  10. pllim commented on Mar 13, 2020

    @pllim
    Member

    Thanks! However, something isn't quite right. The file isn't binary anymore. And while the parsing is instantaneous this time without using much memory, the table looks invalid.

    >>> table = parse_single_table("async_subset.vot", columns=columns)         
    >>> table                                                                   
    <Table length=10000>
    solution_id designation source_id ... datalink_url epoch_photometry_url
                                      ...                                  
       int64       object     int64   ...    object           object       
    ----------- ----------- --------- ... ------------ --------------------
             --          --        -- ...           --                   --
             --          --        -- ...           --                   --
             --          --        -- ...           --                   --
             --          --        -- ...           --                   --
    

    Also, it looks like columns is ignored?

  11. pllim commented on Mar 13, 2020

    @pllim
    Member

    Going back to the 1GB file, I ran this, walked away, came back an hour later, and amazingly it finished. Just posting this here for future reference. So for sure it did not get stuck in a loop somewhere, just eats up lots of memory and takes up to an hour to parse. 😱

    $ volint async_20190630210155.vot 
    Validation report for async_20190630210155.vot
    
    5: W35: 'value' attribute required for INFO elements
    <INFO name="QUERY" value=""><![CDATA[select * from gaiadr2.gaia_sou...
    ^
    
    6: W35: 'value' attribute required for INFO elements
    <INFO name="CAPTION" value=""><![CDATA[How to cite and acknowledge ...
    ^
    
    7: W35: 'value' attribute required for INFO elements
    <INFO name="PAGE" value=""></INFO>
    ^
    
    8: W35: 'value' attribute required for INFO elements
    <INFO name="PAGE_SIZE" value=""></INFO>
    ^
    
    10: W35: 'value' attribute required for INFO elements
    <INFO name="JOBNAME" value=""></INFO>
    ^
    
    47: W06: Invalid UCD 'arith.ratio': Secondary word 'arith.ratio' is
      not valid as a primary word
    <FIELD datatype="float" name="parallax_over_error" ucd="arith.ratio">
    ^
    
    50: W50: Invalid unit string 'mas.yr**-1'
    <FIELD datatype="double" name="pmra" ucd="pos.pm;pos.eq.ra" unit="m...
    ^
    
    53: W50: Invalid unit string 'mas.yr**-1'
    <FIELD datatype="double" name="pmra_error" ucd="stat.error;pos.pm;p...
    ^
    
    56: W50: Invalid unit string 'mas.yr**-1'
    <FIELD datatype="double" name="pmdec" ucd="pos.pm;pos.eq.dec" unit=...
    ^
    
    59: W50: Invalid unit string 'mas.yr**-1'
    <FIELD datatype="double" name="pmdec_error" ucd="stat.error;pos.pm;...
    ^
    
    122: W50: Invalid unit string 'mas**-2'
    <FIELD datatype="float" name="astrometric_weight_al" ucd="stat.weig...
    ^
    
    125: W50: Invalid unit string 'um**-1'
    <FIELD datatype="double" name="astrometric_pseudo_colour" ucd="em.w...
    ^
    
    128: W06: Invalid UCD 'em.wavenumber;stat.error': Primary word
      'stat.error' is not valid as a secondary word
    <FIELD datatype="double" name="astrometric_pseudo_colour_error" ucd...
    ^
    
    128: W50: Invalid unit string 'um**-1'
    <FIELD datatype="double" name="astrometric_pseudo_colour_error" ucd...
    ^
    
    140: W06: Invalid UCD 'pos.errorEllipse;stat.max': Secondary word
      'pos.errorEllipse' is not valid as a primary word
    <FIELD datatype="float" name="astrometric_sigma5d_max" ucd="pos.err...
    ^
    
    155: W50: Invalid unit string ''electron'.s**-1'
    <FIELD datatype="double" name="phot_g_mean_flux" ucd="phot.flux;sta...
    ^
    
    158: W50: Invalid unit string ''electron'.s**-1'
    <FIELD datatype="double" name="phot_g_mean_flux_error" ucd="stat.er...
    ^
    
    161: W06: Invalid UCD 'arith.ratio': Secondary word 'arith.ratio' is
      not valid as a primary word
    <FIELD datatype="float" name="phot_g_mean_flux_over_error" ucd="ari...
    ^
    
    170: W50: Invalid unit string ''electron'.s**-1' (suppressing further
      warnings of this type...)
    <FIELD datatype="double" name="phot_bp_mean_flux" ucd="phot.flux;st...
    ^
    
    176: W06: Invalid UCD 'arith.ratio': Secondary word 'arith.ratio' is
      not valid as a primary word
    <FIELD datatype="float" name="phot_bp_mean_flux_over_error" ucd="ar...
    ^
    
    191: W06: Invalid UCD 'arith.ratio': Secondary word 'arith.ratio' is
      not valid as a primary word
    <FIELD datatype="float" name="phot_rp_mean_flux_over_error" ucd="ar...
    ^
    
    203: W06: Invalid UCD 'phot.color': Unknown word 'phot.color'
    <FIELD datatype="float" name="bp_rp" ucd="phot.color" unit="mag">
    ^
    
    206: W06: Invalid UCD 'phot.color': Unknown word 'phot.color'
    <FIELD datatype="float" name="bp_g" ucd="phot.color" unit="mag">
    ^
    
    209: W06: Invalid UCD 'phot.color': Unknown word 'phot.color'
    <FIELD datatype="float" name="g_rp" ucd="phot.color" unit="mag">
    ^
    
    281: W06: Invalid UCD 'phys.size.radius;stat.error': Primary word
      'stat.error' is not valid as a secondary word (suppressing further
      warnings of this type...)
    <FIELD datatype="float" name="radius_percentile_lower" ucd="phys.si...
    ^
    
  12. pllim commented on Mar 13, 2020

    @pllim
  13. 9 remaining items

  14. jdavies-st commented on Sep 30, 2026

    @jdavies-st
    Contributor

    After having spent time spelunking in the io.votable C internals due to a different issue, I revisited this issue, using the original file (2.5 GB uncompressed, Gaia DR2) and current main branch.

    File is 3,000,000 rows x 96 columns, BINARY2. Big! But not crazy big. Should fit into laptop memory, but doesn't.

    Today, on astropy main branch, speed is OK today; memory is not.

    Parsing takes ~40 us per row and scales linearly with number of rows, so a little over 2 minutes for this file. Peak memory is about 16 GB, more than 6 times the file size, and passing columns= does not reduce. The hour-long runs reported above were likely memory swapping/paging on laptops? My laptop here has a bit more memory than standard, but it also started swapping the full size file, so I made smaller sized versions of the same file for testing - 1%, 5%, 10%, etc. Same columns, fewer rows in the binary data section.

    The cause of the huge memory usage is mostly in iterparse.c, as @pllim found. endElement builds the end tag event's text from a shared buffer but never empties it. Every enclosing end tag that follows then gets its own copy of the last element's text. For a BINARY2 table, , and each carry another full copy of the 2.4 GB stream.

    A toy example is below, showing this using the event iterator and logging the events between tags. If we look at the end tags only:

    import io
    from astropy.utils.xml.iterparser import get_xml_iterator
    
    
    doc = b"<VOTABLE><TABLE><DATA><STREAM>_IM_THE_DATA_</STREAM></DATA></TABLE></VOTABLE>"
    with get_xml_iterator(io.BytesIO(doc)) as event:
        print(
            [(tag, data) for (start, tag, data, pos) in event if not start]
        )
    # [('STREAM', '_IM_THE_DATA_'), ('DATA', '_IM_THE_DATA_'), ('TABLE', '_IM_THE_DATA_'), ('VOTABLE', '_IM_THE_DATA_')]

    The pure-Python parser does roughly the same, so moving from the default fast parser to the python one doesn't help.

    So fixing both of these would help reduce memory.

    There's probably some smaller memory redundancies to add to this:

    • Decoding makes an extra copy first. _get_binary_data_stream decodes the stream with base64.b64decode(text.encode("ascii")). This step makes a copy of all 2.4 GB in order to turn the text into bytes. There's a one-liner to do this without making a copy.
    • The result table is copied as it grows. This 2.4 GB input file doesn't say how many rows it has (the optional nrows attribute on TABLE). Typical of VOT query results. So the result array starts small, and each time it fills up it is replaced by one 1.5 times larger, with every row read so far copied across. At the end it is copied once more to trim it to the exact number of rows. During each copy, the old and new arrays are both in memory, so its probably adding an extra 1.5x size in memory here as well.

    I don't think the earlier fix (#10076) changed the memory use. The tokenizer doubles its text buffer each time the text outgrows it (1 GB, 2 GB, 4 GB, and so on), and #10076 corrected how that next size is calculated above 4 GB. This file's text is 2.4 GB, so the old calculation was already OK for it.

    So there's some low-hanging fruit here. I have not looked at the behavior in reading just 2 columns, other than to say it doesn't seem to change memory usage, as already reported in this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions