Table.read(filename) is 10 times slower than Table(fits.getdata(filename))

Hey table team --

I have a ~1.5 GB FITS file with ~100 columns, and noticed the following:

Is this expected, or a known performance issue? I didn't see a reference to this in the docs or currently open issues, but may have missed it...

This is with Astropy v3.0.1.

The difference may be due to memmap, can you try with Table.read(..., memmap=True) ?

Doesn't look like it:

and

@adrn

@adrn , try to profile the slow case and see where the bottleneck is.

If you give it format='fits', does it load faster?

Also, to rule out overhead of first-time imports, time the faster one first before the slower one and see.

First 16 lines of profiling:

%%prun -s cumulative
Table.read('Gaia-DR2-mock-200pc.fits')

         906834 function calls (885812 primitive calls) in 67.236 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      4/1    0.000    0.000   67.236   67.236 {built-in method builtins.exec}
        1    0.000    0.000   67.236   67.236 <string>:2(<module>)
        1    0.000    0.000   67.236   67.236 table.py:2515(read)
        1    0.000    0.000   67.200   67.200 registry.py:480(read)
      2/1    0.048    0.024   67.196   67.196 connect.py:115(read_table_fits)
      396    0.005    0.000   63.733    0.161 column.py:1100(__new__)
      396    0.006    0.000   63.668    0.161 core.py:2771(__new__)
       99    2.512    0.025   63.608    0.643 fromnumeric.py:1127(resize)
      178   61.090    0.343   61.090    0.343 {built-in method numpy.core.multiarray.concatenate}
 1401/400    0.002    0.000    1.784    0.004 decorators.py:704(__get__)
        1    0.000    0.000    1.712    1.712 table.py:405(data)
        1    0.000    0.000    1.712    1.712 table.py:154(_get_tbdata)
        1    0.000    0.000    1.682    1.682 base.py:462(_get_raw_data)
        1    0.000    0.000    1.682    1.682 file.py:246(readarray)
        1    0.000    0.000    1.682    1.682 util.py:554(_array_from_file)
        1    1.681    1.681    1.681    1.681 {built-in method numpy.core.multiarray.fromfile}

Also, to rule out overhead of first-time imports, time the faster one first before the slower one and see.

The lines in #7399 (comment) were run after the cells in #7399 (comment) so I think that already rules out first-time imports.

This jumped out

 178   61.090    0.343   61.090    0.343 {built-in method numpy.core.multiarray.concatenate}

Yea, exactly - that concatenate looks culpable.

If you give it format='fits', does it load faster?

Nope.

What does the faster case prun look like?

Faster case:

%%prun -s cumulative
Table(fits.getdata('Gaia-DR2-mock-200pc.fits'))

         183070 function calls (176977 primitive calls) in 5.007 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    5.007    5.007 {built-in method builtins.exec}
        1    0.025    0.025    5.007    5.007 <string>:2(<module>)
        1    0.000    0.000    4.804    4.804 table.py:279(__init__)
        1    0.000    0.000    4.804    4.804 table.py:691(_init_from_ndarray)
        1    0.001    0.001    4.798    4.798 table.py:648(_init_from_list)
       99    0.000    0.000    4.790    0.048 column.py:819(__new__)
       99    0.002    0.000    4.790    0.048 column.py:182(__new__)
       99    4.772    0.048    4.772    0.048 {built-in method numpy.core.multiarray.array}
        1    0.000    0.000    0.178    0.178 convenience.py:118(getdata)
 1405/404    0.001    0.000    0.146    0.000 decorators.py:704(__get__)
        1    0.000    0.000    0.146    0.146 table.py:405(data)
        1    0.000    0.000    0.145    0.145 table.py:154(_get_tbdata)
        2    0.000    0.000    0.082    0.041 column.py:1301(__init__)
        1    0.000    0.000    0.059    0.059 base.py:462(_get_raw_data)
        1    0.000    0.000    0.059    0.059 file.py:246(readarray)
        1    0.058    0.058    0.059    0.059 memmap.py:202(__new__)

And the "slow case" with memmap=True:

%%prun -s cumulative
Table.read('Gaia-DR2-mock-200pc.fits', memmap=True)

         903451 function calls (882655 primitive calls) in 56.506 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      4/1    0.000    0.000   56.506   56.506 {built-in method builtins.exec}
        1    0.000    0.000   56.506   56.506 <string>:2(<module>)
        1    0.000    0.000   56.506   56.506 table.py:2515(read)
        1    0.000    0.000   56.473   56.473 registry.py:480(read)
      2/1    0.044    0.022   56.471   56.471 connect.py:115(read_table_fits)
      396    0.004    0.000   54.367    0.137 column.py:1100(__new__)
      396    0.005    0.000   54.310    0.137 core.py:2771(__new__)
       99    1.938    0.020   54.256    0.548 fromnumeric.py:1127(resize)
      178   52.312    0.294   52.312    0.294 {built-in method numpy.core.multiarray.concatenate}
       20    0.000    0.000    1.410    0.070 core.py:4030(__eq__)
       20    0.000    0.000    1.410    0.070 core.py:3976(_comparison)
       20    1.357    0.068    1.358    0.068 {built-in method _operator.eq}
        1    0.001    0.001    0.299    0.299 connect.py:69(_decode_mixins)
 1403/402    0.003    0.000    0.238    0.001 decorators.py:704(__get__)
        1    0.000    0.000    0.207    0.207 meta.py:298(get_header_from_yaml)
        1    0.001    0.001    0.204    0.204 __init__.py:65(load)

Hmm, Time conversion should only happen if astropy_native=True which is not the case by default... so maybe something else.

@adrn

The following lines suggest to me that there may be mix-in columns declared as YAML in the FITS header:

        1    0.001    0.001    0.299    0.299 connect.py:69(_decode_mixins)
        1    0.000    0.000    0.207    0.207 meta.py:298(get_header_from_yaml)

@adrn - did you manage to upload the file somewhere?

Tagging myself because I might be of help. Would be useful to have a self-contained test case, with data

@adrn

@adrn - Could you upload your file to somewhere?

File is here, sorry!
https://www.astro.princeton.edu/~adrn/Gaia-DR2-mock-200pc.fits

@astrofrog

As @astrofrog said, the file has mixin columns declaration in the FITS header (COMMENT --BEGIN-ASTROPY-SERIALIZED-COLUMNS--). Hence, fits.getdata will definitely be faster.

On another note, there are definitely places where Table.read() can be made faster when astropy_native=True. But that can be handled in a separate PR.

If mix-in columns are being used it may just be a matter of making sure we set copy=False when instantiating those objects? (since there's no reason a copy should be made). I don't have time to investigate this week, but this seems like a good #pyastro18 hack? :)

I haven't gone through the mixin specification code in much detail, but it is definitely worth considering how Table.read could be made easier in terms of user perspective. P. S. My bad, but I am definitely getting a little bit confused 😕 having both mixin yaml by default and astropy_native (although it is just for time) as an option. (correct me if I'm wrong)

I don't believe there are no bona-fide "mixin columns" in this file. All the columns are just standard Column types with the meta-data providing all the datatypes, formats, descriptions, and column meta (ucd's). A key thing to note is at the end of the COMMENTs:

COMMENT meta:                                                                   
COMMENT   __serialized_columns__: {}                                            
COMMENT --END-ASTROPY-SERIALIZED-COLUMNS--

The fact that __serialized_columns__ is an empty dict means there are no mixin-columns (i.e. a SkyCoord or Time or Quantity). Below is what mixins look like in a FITS file, so I'm a bit confused about why concatenate is being called and burning all the CPU.

In [7]: t = QTable([[1, 2] * u.m, SkyCoord([1,2], [3,4], unit='deg'), Time([1,2], format='cxcsec')])

In [8]: t.write('test.fits', overwrite=True)

In [9]: hdus = fits.open('test.fits')

In [10]: hdus[1].header
Out[10]: 
XTENSION= 'BINTABLE'           / binary table extension                         
BITPIX  =                    8 / array data type                                
NAXIS   =                    2 / number of array dimensions                     
NAXIS1  =                   40 / length of dimension 1                          
NAXIS2  =                    2 / length of dimension 2                          
PCOUNT  =                    0 / number of group parameters                     
GCOUNT  =                    1 / number of groups                               
TFIELDS =                    4 / number of table fields                         
TIMESYS = 'UTC     '           / Default time scale                             
JDREF   =                  0.0 / Time columns are jd = jd1 + jd2                
TREFPOS = 'TOPOCENTER'         / Time reference position                        
TTYPE1  = 'col0    '                                                            
TFORM1  = 'D       '                                                            
TUNIT1  = 'm       '                                                            
TTYPE2  = 'col1.ra '                                                            
TFORM2  = 'D       '                                                            
TUNIT2  = 'deg     '                                                            
TTYPE3  = 'col1.dec'                                                            
TFORM3  = 'D       '                                                            
TUNIT3  = 'deg     '                                                            
TTYPE4  = 'col2    '                                                            
TFORM4  = '2D      '                                                            
TUNIT4  = 'd       '                                                            
TCTYP4  = 'TT      '                                                            
TCUNI4  = 'd       '                                                            
TRPOS4  = ''                                                                    
COMMENT --BEGIN-ASTROPY-SERIALIZED-COLUMNS--                                    
COMMENT datatype:                                                               
COMMENT - {name: col0, unit: m, datatype: float64}                              
COMMENT - {name: col1.ra, unit: deg, datatype: float64}                         
COMMENT - {name: col1.dec, unit: deg, datatype: float64}                        
COMMENT - {name: col2, datatype: object}                                        
COMMENT meta:                                                                   
COMMENT   __serialized_columns__:                                               
COMMENT     col0:                                                               
COMMENT       __class__: astropy.units.quantity.Quantity                        
COMMENT       value: !astropy.table.SerializedColumn {name: col0}               
COMMENT     col1:                                                               
COMMENT       __class__: astropy.coordinates.sky_coordinate.SkyCoord            
COMMENT       dec: !astropy.table.SerializedColumn                              
COMMENT         __class__: astropy.coordinates.angles.Latitude                  
COMMENT         value: !astropy.table.SerializedColumn {name: col1.dec}         
COMMENT       frame: icrs                                                       
COMMENT       ra: !astropy.table.SerializedColumn                               
COMMENT         __class__: astropy.coordinates.angles.Longitude                 
COMMENT         value: !astropy.table.SerializedColumn {name: col1.ra}          
COMMENT         wrap_angle: !astropy.coordinates.Angle                          
COMMENT           unit: !astropy.units.Unit {unit: deg}                         
COMMENT           value: 360.0                                                  
COMMENT       representation_type: spherical                                    
COMMENT --END-ASTROPY-SERIALIZED-COLUMNS--

FYI

In [13]: dat = Table.read('Gaia-DR2-mock-200pc.fits')

In [14]: dat.has_mixin_columns
Out[14]: False

OK, well I at least have a top-level cause:

When using Table.read(file) it is using the connnect.py code which pays attention to the NULL values.
This particular file actually has specified NULL values for a number of columns.
This causes read_table_fits to use a masked table and thus MaskedColumn for all the columns (so it can properly mask column entries that correspond to the FITS NULL value for that column).

BUT, for some reason I have not yet looked at, MaskedColumn is fantastically slow to initialize:

In [8]: d = np.arange(1e7)

In [9]: time x = Column(d)
CPU times: user 304 µs, sys: 8.24 ms, total: 8.54 ms
Wall time: 8.74 ms

In [10]: time x = MaskedColumn(d)
CPU times: user 2.08 s, sys: 43.1 ms, total: 2.12 s
Wall time: 2.13 s

I cannot blame masked array here:

In [12]: time x = np.ma.MaskedArray(d)
CPU times: user 74 µs, sys: 1 µs, total: 75 µs
Wall time: 79.9 µs

Given the dis-proportionate time spent in sys compared to user, I am going to guess (multiple?) malloc's are occurring.

See #7422 for a fix.

Navigation Menu

Repository navigation

Table.read(filename) is 10 times slower than Table(fits.getdata(filename)) #7399

17 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Table.read(filename) is 10 times slower than Table(fits.getdata(filename)) #7399

Description

Activity

saimn commented on Apr 23, 2018

adrn commented on Apr 23, 2018

pllim commented on Apr 23, 2018

pllim commented on Apr 23, 2018

pllim commented on Apr 23, 2018

adrn commented on Apr 23, 2018

adrn commented on Apr 23, 2018

pllim commented on Apr 23, 2018

adrn commented on Apr 23, 2018

pllim commented on Apr 23, 2018

adrn commented on Apr 23, 2018

adrn commented on Apr 23, 2018

17 remaining items

saimn commented on Apr 25, 2018

astrofrog commented on Apr 26, 2018

manodeep commented on May 1, 2018

bsipocz commented on May 1, 2018

adrn commented on May 2, 2018

aaryapatil commented on May 2, 2018

aaryapatil commented on May 2, 2018

astrofrog commented on May 2, 2018

aaryapatil commented on May 2, 2018

taldcroft commented on May 2, 2018

taldcroft commented on May 2, 2018

taldcroft commented on May 2, 2018

manodeep commented on May 2, 2018

taldcroft commented on May 3, 2018

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions