FITS: Performance issue

In this FITS file reading out the .data object of the 6th (0-indexed counting), the HDU named "Observation" takes over 3 minutes on my iMac 5K.
The table indicates a total size of 16 MB:

data.itemsize
16777661

but I don't believe that should be an issue, as indicated by our IDL reader, that has no noticeable delay in opening that file.
In case this is not an easy-to-fix performance bug with pyfits: Our group is creating these files, we can't change the structure of the files in terms of where is stored what, but maybe there are some flags that we can use to improve the structure internally on the binary level somehow?

Here's the code I used to show the issue:

from astropy.io import fits
import time
fname = 'mvn_iuv_l1a_periapse-orbit01063-muvdark_20150417T234058_v02_r01.fits.gz'
hdulist = fits.open(fname)
t0 = time.time()
data = hdulist[6].data
print(time.time() - t0)

193.38006591796875

Note, that I tried if gunzipping the file makes any difference, and it doesn't, AFAICS.

Weird--the data loaded immediately for me. You'll have to tell me more about the Python version and the platform.

Just to make sure I have the right data, is the table in question supposed to have only one row?

How do you define row? len(data) is 1, yes, but there's lot's of stuff in it. My system is OSX, Miniconda distribution, both Python 2 and 3 show this. Will try with github astropy now.

Just look at data.names to see all the tables in there:

['PRODUCT_ID',
 'COLLECTION_ID',
 'BUNDLE_ID',
 'CODE_SVN_REVISION',
 'ANC_SVN_REVISION',
 'PRODUCT_CREATION_DATE',
 'OBSERVATION_TYPE',
 'MISSION_PHASE',
 'TARGET_NAME',
 'ORBIT_SEGMENT',
 'ORBIT_NUMBER',
 'SOLAR_LONGITUDE',
 'GRATING_SELECT',
 'KEYHOLE_SELECT',
 'BIN_PATTERN_INDEX',
 'CADENCE',
 'INT_TIME',
 'DUTY_CYCLE',
 'CHANNEL',
 'WAVELENGTH',
 'WAVELENGTH_WIDTH',
 'KERNELS']

It's really weird, even with 1-element fields though, it takes 3 seconds!! or so to get the prompt back when I do:

t0 = time.time()
print(data['MISSION_PHASE'])
print(time.time() - t0)

['PRIME']
3.31076288223

Yes, there's one row with many multi-element fields. Loading the table, or any individual column, took under a second for me.

Have you ever used kern_prof?

Just so that you don't think it's my computer, I did the same with another file:

# first timer
0.189756155014
# second timer
['PRIME']
0.00368285179138

No experience with kern_prof, but willing to learn. I tried with astropy master, to no avail.

It's not that I think it's your computer. I just want to narrow down things like the Numpy version, etc. The OS could matter too.

Actually, instead of going straight to kernprof (since I'm not really sure what functions you need to be profiling) it might be nice if you made a simple test script that simply opens that file and loads the data (such that it demonstrates the slowdown), and then run python -m cProfile --sort=cumtime test_script.py and copy the basic profiler output first. Might help give an idea....

I used pandas.show_versions() for the current stuff in miniconda:

INSTALLED VERSIONS
------------------
commit: None
python: 2.7.10.final.0
python-bits: 64
OS: Darwin
OS-release: 14.5.0
machine: x86_64
processor: i386
byteorder: little
LC_ALL: None
LANG: en_US.UTF-8

pandas: 0.17.0
nose: 1.3.7
pip: 7.1.2
setuptools: 18.4
Cython: 0.23.4
numpy: 1.10.1
scipy: 0.16.0
statsmodels: None
IPython: 4.0.0
sphinx: None
patsy: None
dateutil: 2.4.2
pytz: 2015.6
blosc: None
bottleneck: None
tables: 3.2.2
numexpr: 2.4.4
matplotlib: 1.4.3
openpyxl: None
xlrd: None
xlwt: None
xlsxwriter: None
lxml: None
bs4: None
html5lib: None
httplib2: None
apiclient: None
sqlalchemy: 1.0.9
pymysql: None
psycopg2: None

Oh I see, this is your problem:

numpy: 1.10.1

Let me see if this is fixed in #4228

Wow, never would have thought that. Thanks!

Yeah, even on numpy master it's still spending an incredible amount of time in those functions:

       44    0.001    0.000  570.352   12.963 records.py:543(field)
       44    2.667    0.061  570.351   12.963 {method 'getfield' of 'numpy.ndarray' objects}
       44    5.754    0.131  567.681   12.902 _internal.py:397(_getfield_is_safe)
       45  218.477    4.855  410.559    9.124 _internal.py:344(_check_field_overlap)

For reference, Michael's table has 22 fields, so in the process of reading and printing the table each field is accessed twice (I think for pyfits anyways this is normal). Each field access is taking almost 13 seconds on my system. Times 44 that's nearly 10 minutes right there... :(

At the same time, I made a plain Numpy array using the same dtype as that table and didn't have any noticeable problem. So maybe there's something crazy going on at our side too....

Probably the best one can do right now is to see if one can construct an equivalent recarray-only case which clearly still is much slower on master than on 1.9, and then post it to numpy/numpy#6467.

@ahaldane

Sorry, it seems I'm getting in a habit of commenting when you are just writing what I thought... So, partly it is on our side, although the number of calls to things in _internal.py seem more than a little strange. Line 366 in that file is:

def _get_all_field_offsets(dtype, base_offset=0):
...
            fields.extend((typ, off + dtype.base.itemsize*j)
                           for j in range(count) for (typ, off) in sub_offsets)

It is part of a section that was changed in the PR that made recarray so slow. cc @ahaldane just in case he has ideas.

Note the fix has not been merged into numpy master yet

@esheldon

@esheldon numpy/numpy#6208 has been merged, and that's the only fix to this I'm aware of? Or is there another. I confirmed that I was testing against it.

@mhvk The test case I just added in numpy/numpy#6467 (comment) is totally independent of anything particularly weird astropy does (except maybe assigning a new dtype to an existing array but with a different byte order?)

@embray

@embray Yeah, sorry, I thought I was getting email updates about that that pull request but I wasn't.

@embray

@embray - good that you could narrow it down. Hopefully, there will be a fix soon.

Added changelog entries for the working fixes in astropy#4228, and al…

@michaelaye

@michaelaye - with the recent versions of numpy master and maintenance/1.10.x (see numpy/numpy#6562) this issue is resolved on my system. So, I'm closing this, but feel free to reopen if it turns out there still is a problem (if so, also note at numpy/numpy#6467). And: thanks for the report -- nice to see us helping numpy get better! -- or at least not get worse...

Added changelog entries for the working fixes in astropy#4228, and al…

Navigation Menu

Repository navigation

FITS: Performance issue #4259

12 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

FITS: Performance issue #4259

Description

Activity

michaelaye commented on Oct 21, 2015

embray commented on Oct 22, 2015

embray commented on Oct 22, 2015

michaelaye commented on Oct 22, 2015

michaelaye commented on Oct 22, 2015

michaelaye commented on Oct 22, 2015

embray commented on Oct 22, 2015

michaelaye commented on Oct 22, 2015

michaelaye commented on Oct 22, 2015

embray commented on Oct 22, 2015

michaelaye commented on Oct 22, 2015

embray commented on Oct 22, 2015

michaelaye commented on Oct 22, 2015

12 remaining items

embray commented on Oct 22, 2015

embray commented on Oct 22, 2015

mhvk commented on Oct 22, 2015

mhvk commented on Oct 22, 2015

esheldon commented on Oct 22, 2015

embray commented on Oct 22, 2015

esheldon commented on Oct 22, 2015

mhvk commented on Oct 22, 2015

mhvk commented on Oct 27, 2015

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions