Repository navigation
test_c_reader tests extremely slow on MacOS X with Python 3.8 #9864
Description
The ASCII C reader tests are extremely slow (>5 minutes for just those tests) on my Mac (10.15) with Python 3.8 - I suspect maybe due to the change in default multiprocessing method to 'spawn' (this is a Python change):
% pytest astropy/io/ascii/tests/test_c_reader.py --durations=50 -v
Internet access disabled
================================================================= test session starts =================================================================
platform darwin -- Python 3.8.0, pytest-5.3.3.dev61+g4a265ba38.d20200114, py-1.8.0, pluggy-0.13.0 -- /Users/tom/python/dev/bin/python3.8
cachedir: .pytest_cache
Matplotlib: 3.1.1+2995.gbdcd9fcc3
Freetype: 2.6.1
hypothesis profile 'default' -> database=DirectoryBasedExampleDatabase('/Users/tom/tmp/astropy/.hypothesis/examples')
Running tests with Astropy version 4.1.dev27325.
Running tests in astropy/io/ascii/tests/test_c_reader.py.
Date: 2020-01-16T22:07:43
Platform: macOS-10.15.2-x86_64-i386-64bit
Executable: /Users/tom/python/dev/bin/python3.8
Full Python Version:
3.8.0 (v3.8.0:fa919fdf25, Oct 14 2019, 10:23:27)
[Clang 6.0 (clang-600.0.57)]
encodings: sys: utf-8, locale: UTF-8, filesystem: utf-8
byteorder: little
float info: dig: 15, mant_dig: 15
Package versions:
Numpy: 1.18.0
Scipy: 1.3.2
Matplotlib: 3.1.1+2995.gbdcd9fcc3
h5py: 2.10.0
Pandas: 0.25.3
Cython: 0.29.14
Scikit-image: 0.16.2
asdf: 2.4.2
astropy-helpers: 4.0.1
Using Astropy options: remote_data: none.
rootdir: /Users/tom/tmp/astropy, inifile: setup.cfg
plugins: mpl-0.11, repeat-0.8.0, arraydiff-0.3, remotedata-0.3.2, hypothesis-5.1.2, asdf-2.4.2, cov-2.8.1, astropy-header-0.1.2, build-0.1.dev0, doctestplus-0.5.1.dev5+gd3d2207.d20191229, filter-subpackage-0.1.1, openfiles-0.5.0.dev0
collecting ... pytest_ignore_collect in doctestplus
pytest_ignore_collect in doctestplus
pytest_ignore_collect in doctestplus
pytest_ignore_collect in doctestplus
collected 136 items
astropy/io/ascii/tests/test_c_reader.py::test_simple_data[True] PASSED [ 0%]
astropy/io/ascii/tests/test_c_reader.py::test_simple_data[False] PASSED [ 1%]
astropy/io/ascii/tests/test_c_reader.py::test_read_types PASSED [ 2%]
astropy/io/ascii/tests/test_c_reader.py::test_supplied_names[True] PASSED [ 2%]
astropy/io/ascii/tests/test_c_reader.py::test_supplied_names[False] PASSED [ 3%]
astropy/io/ascii/tests/test_c_reader.py::test_no_header[True] PASSED [ 4%]
astropy/io/ascii/tests/test_c_reader.py::test_no_header[False] PASSED [ 5%]
astropy/io/ascii/tests/test_c_reader.py::test_no_header_supplied_names[True] PASSED [ 5%]
astropy/io/ascii/tests/test_c_reader.py::test_no_header_supplied_names[False] PASSED [ 6%]
astropy/io/ascii/tests/test_c_reader.py::test_comment[True] PASSED [ 7%]
astropy/io/ascii/tests/test_c_reader.py::test_comment[False] PASSED [ 8%]
astropy/io/ascii/tests/test_c_reader.py::test_empty_lines[True] PASSED [ 8%]
astropy/io/ascii/tests/test_c_reader.py::test_empty_lines[False] PASSED [ 9%]
astropy/io/ascii/tests/test_c_reader.py::test_lstrip_whitespace[True] PASSED [ 10%]
astropy/io/ascii/tests/test_c_reader.py::test_lstrip_whitespace[False] PASSED [ 11%]
astropy/io/ascii/tests/test_c_reader.py::test_rstrip_whitespace[True] PASSED [ 11%]
astropy/io/ascii/tests/test_c_reader.py::test_rstrip_whitespace[False] PASSED [ 12%]
astropy/io/ascii/tests/test_c_reader.py::test_conversion[True] PASSED [ 13%]
astropy/io/ascii/tests/test_c_reader.py::test_conversion[False] PASSED [ 13%]
astropy/io/ascii/tests/test_c_reader.py::test_delimiter[True] PASSED [ 14%]
astropy/io/ascii/tests/test_c_reader.py::test_delimiter[False] PASSED [ 15%]
astropy/io/ascii/tests/test_c_reader.py::test_include_names[True] PASSED [ 16%]
astropy/io/ascii/tests/test_c_reader.py::test_include_names[False] PASSED [ 16%]
astropy/io/ascii/tests/test_c_reader.py::test_exclude_names[True] PASSED [ 17%]
astropy/io/ascii/tests/test_c_reader.py::test_exclude_names[False] PASSED [ 18%]
astropy/io/ascii/tests/test_c_reader.py::test_include_exclude_names[True] PASSED [ 19%]
astropy/io/ascii/tests/test_c_reader.py::test_include_exclude_names[False] PASSED [ 19%]
astropy/io/ascii/tests/test_c_reader.py::test_doubled_quotes PASSED [ 20%]
astropy/io/ascii/tests/test_c_reader.py::test_doubled_quotes_segv PASSED [ 21%]
astropy/io/ascii/tests/test_c_reader.py::test_quoted_fields[True] XFAIL [ 22%]
astropy/io/ascii/tests/test_c_reader.py::test_quoted_fields[False] PASSED [ 22%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[delimiter-,,] PASSED [ 23%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[comment-##] PASSED [ 24%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[data_start-None] PASSED [ 25%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[data_start--1] PASSED [ 25%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[quotechar-##] PASSED [ 26%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[header_start--1] PASSED [ 27%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[converters-val6] PASSED [ 27%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[Inputter-ContinuationLinesInputter] PASSED [ 28%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[header_Splitter-DefaultSplitter] PASSED [ 29%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters[data_Splitter-DefaultSplitter] PASSED [ 30%]
astropy/io/ascii/tests/test_c_reader.py::test_invalid_parameters_other PASSED [ 30%]
astropy/io/ascii/tests/test_c_reader.py::test_too_many_cols1 PASSED [ 31%]
astropy/io/ascii/tests/test_c_reader.py::test_too_many_cols2 PASSED [ 32%]
astropy/io/ascii/tests/test_c_reader.py::test_too_many_cols3 PASSED [ 33%]
astropy/io/ascii/tests/test_c_reader.py::test_not_enough_cols[True] PASSED [ 33%]
astropy/io/ascii/tests/test_c_reader.py::test_not_enough_cols[False] PASSED [ 34%]
astropy/io/ascii/tests/test_c_reader.py::test_data_end[True] PASSED [ 35%]
astropy/io/ascii/tests/test_c_reader.py::test_data_end[False] PASSED [ 36%]
astropy/io/ascii/tests/test_c_reader.py::test_inf_nan[True] PASSED [ 36%]
astropy/io/ascii/tests/test_c_reader.py::test_inf_nan[False] PASSED [ 37%]
astropy/io/ascii/tests/test_c_reader.py::test_fill_values[True] PASSED [ 38%]
astropy/io/ascii/tests/test_c_reader.py::test_fill_values[False] PASSED [ 38%]
astropy/io/ascii/tests/test_c_reader.py::test_fill_include_exclude_names[True] PASSED [ 39%]
astropy/io/ascii/tests/test_c_reader.py::test_fill_include_exclude_names[False] PASSED [ 40%]
astropy/io/ascii/tests/test_c_reader.py::test_many_rows[True] PASSED [ 41%]
astropy/io/ascii/tests/test_c_reader.py::test_many_rows[False] PASSED [ 41%]
astropy/io/ascii/tests/test_c_reader.py::test_many_columns[True] PASSED [ 42%]
astropy/io/ascii/tests/test_c_reader.py::test_many_columns[False] PASSED [ 43%]
astropy/io/ascii/tests/test_c_reader.py::test_fast_reader PASSED [ 44%]
astropy/io/ascii/tests/test_c_reader.py::test_read_tab[True] XFAIL [ 44%]
astropy/io/ascii/tests/test_c_reader.py::test_read_tab[False] PASSED [ 45%]
astropy/io/ascii/tests/test_c_reader.py::test_default_data_start[True] PASSED [ 46%]
astropy/io/ascii/tests/test_c_reader.py::test_default_data_start[False] PASSED [ 47%]
astropy/io/ascii/tests/test_c_reader.py::test_commented_header[True] PASSED [ 47%]
astropy/io/ascii/tests/test_c_reader.py::test_commented_header[False] PASSED [ 48%]
astropy/io/ascii/tests/test_c_reader.py::test_rdb[True] PASSED [ 49%]
astropy/io/ascii/tests/test_c_reader.py::test_rdb[False] PASSED [ 50%]
astropy/io/ascii/tests/test_c_reader.py::test_data_start[True] XFAIL [ 50%]
astropy/io/ascii/tests/test_c_reader.py::test_data_start[False] PASSED [ 51%]
astropy/io/ascii/tests/test_c_reader.py::test_quoted_empty_values[True] XFAIL [ 52%]
astropy/io/ascii/tests/test_c_reader.py::test_quoted_empty_values[False] PASSED [ 52%]
astropy/io/ascii/tests/test_c_reader.py::test_csv_comment_default[True] PASSED [ 53%]
astropy/io/ascii/tests/test_c_reader.py::test_csv_comment_default[False] PASSED [ 54%]
astropy/io/ascii/tests/test_c_reader.py::test_whitespace_before_comment[True] PASSED [ 55%]
astropy/io/ascii/tests/test_c_reader.py::test_whitespace_before_comment[False] PASSED [ 55%]
astropy/io/ascii/tests/test_c_reader.py::test_strip_line_trailing_whitespace[True] PASSED [ 56%]
astropy/io/ascii/tests/test_c_reader.py::test_strip_line_trailing_whitespace[False] PASSED [ 57%]
astropy/io/ascii/tests/test_c_reader.py::test_no_data[True] PASSED [ 58%]
astropy/io/ascii/tests/test_c_reader.py::test_no_data[False] PASSED [ 58%]
astropy/io/ascii/tests/test_c_reader.py::test_line_endings[True] PASSED [ 59%]
astropy/io/ascii/tests/test_c_reader.py::test_line_endings[False] PASSED [ 60%]
astropy/io/ascii/tests/test_c_reader.py::test_store_comments[True] PASSED [ 61%]
astropy/io/ascii/tests/test_c_reader.py::test_store_comments[False] PASSED [ 61%]
astropy/io/ascii/tests/test_c_reader.py::test_empty_quotes[True] PASSED [ 62%]
astropy/io/ascii/tests/test_c_reader.py::test_empty_quotes[False] PASSED [ 63%]
astropy/io/ascii/tests/test_c_reader.py::test_fast_tab_with_names[True] PASSED [ 63%]
astropy/io/ascii/tests/test_c_reader.py::test_fast_tab_with_names[False] PASSED [ 64%]
astropy/io/ascii/tests/test_c_reader.py::test_read_big_table SKIPPED [ 65%]
astropy/io/ascii/tests/test_c_reader.py::test_read_big_table2 SKIPPED [ 66%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[False-False-True] SKIPPED [ 66%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[False-False-False] SKIPPED [ 67%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[False-fast_reader1-True] SKIPPED [ 68%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[False-fast_reader1-False] SKIPPED [ 69%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[False-fast_reader2-True] PASSED [ 69%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[False-fast_reader2-False] PASSED [ 70%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-False-True] SKIPPED [ 71%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-False-False] SKIPPED [ 72%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-fast_reader1-True] SKIPPED [ 72%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-fast_reader1-False] SKIPPED [ 73%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-fast_reader2-True] PASSED [ 74%]
astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-fast_reader2-False] PASSED [ 75%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[False-False-True] SKIPPED [ 75%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[False-False-False] SKIPPED [ 76%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[False-fast_reader1-True] PASSED [ 77%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[False-fast_reader1-False] PASSED [ 77%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[False-fast_reader2-True] PASSED [ 78%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[False-fast_reader2-False] PASSED [ 79%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-False-True] SKIPPED [ 80%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-False-False] SKIPPED [ 80%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-fast_reader1-True] SKIPPED [ 81%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-fast_reader1-False] SKIPPED [ 82%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-fast_reader2-True] SKIPPED [ 83%]
astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-fast_reader2-False] SKIPPED [ 83%]
astropy/io/ascii/tests/test_c_reader.py::test_int_out_of_range[False-True] PASSED [ 84%]
astropy/io/ascii/tests/test_c_reader.py::test_int_out_of_range[False-False] PASSED [ 85%]
astropy/io/ascii/tests/test_c_reader.py::test_int_out_of_range[True-True] PASSED [ 86%]
astropy/io/ascii/tests/test_c_reader.py::test_int_out_of_range[True-False] PASSED [ 86%]
astropy/io/ascii/tests/test_c_reader.py::test_int_out_of_order[True] PASSED [ 87%]
astropy/io/ascii/tests/test_c_reader.py::test_int_out_of_order[False] PASSED [ 88%]
astropy/io/ascii/tests/test_c_reader.py::test_fortran_reader[False-True] PASSED [ 88%]
astropy/io/ascii/tests/test_c_reader.py::test_fortran_reader[False-False] PASSED [ 89%]
astropy/io/ascii/tests/test_c_reader.py::test_fortran_reader[True-True] PASSED [ 90%]
astropy/io/ascii/tests/test_c_reader.py::test_fortran_reader[True-False] PASSED [ 91%]
astropy/io/ascii/tests/test_c_reader.py::test_fortran_invalid_exp[False-True] PASSED [ 91%]
astropy/io/ascii/tests/test_c_reader.py::test_fortran_invalid_exp[False-False] PASSED [ 92%]
astropy/io/ascii/tests/test_c_reader.py::test_fortran_invalid_exp[True-True] PASSED [ 93%]
astropy/io/ascii/tests/test_c_reader.py::test_fortran_invalid_exp[True-False] PASSED [ 94%]
astropy/io/ascii/tests/test_c_reader.py::test_fortran_reader_notbasic PASSED [ 94%]
astropy/io/ascii/tests/test_c_reader.py::test_dict_kwarg_integrity[fast_reader0-True] PASSED [ 95%]
astropy/io/ascii/tests/test_c_reader.py::test_dict_kwarg_integrity[fast_reader0-False] PASSED [ 96%]
astropy/io/ascii/tests/test_c_reader.py::test_dict_kwarg_integrity[fast_reader1-True] PASSED [ 97%]
astropy/io/ascii/tests/test_c_reader.py::test_dict_kwarg_integrity[fast_reader1-False] PASSED [ 97%]
astropy/io/ascii/tests/test_c_reader.py::test_read_empty_basic_table_with_comments[False] PASSED [ 98%]
astropy/io/ascii/tests/test_c_reader.py::test_read_empty_basic_table_with_comments[fast_reader1] PASSED [ 99%]
astropy/io/ascii/tests/test_c_reader.py::test_read_empty_basic_table_with_comments[fast_reader2] PASSED [100%]
============================================================== slowest 50 test durations ==============================================================
27.95s call astropy/io/ascii/tests/test_c_reader.py::test_delimiter[True]
26.18s call astropy/io/ascii/tests/test_c_reader.py::test_data_end[True]
21.19s call astropy/io/ascii/tests/test_c_reader.py::test_line_endings[True]
20.89s call astropy/io/ascii/tests/test_c_reader.py::test_fortran_invalid_exp[True-True]
16.59s call astropy/io/ascii/tests/test_c_reader.py::test_fill_values[True]
15.64s call astropy/io/ascii/tests/test_c_reader.py::test_commented_header[True]
14.95s call astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-fast_reader1-True]
12.98s call astropy/io/ascii/tests/test_c_reader.py::test_fill_include_exclude_names[True]
10.92s call astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-fast_reader2-True]
10.44s call astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-fast_reader1-False]
9.89s call astropy/io/ascii/tests/test_c_reader.py::test_data_at_range_limit[True-fast_reader2-False]
7.69s call astropy/io/ascii/tests/test_c_reader.py::test_fortran_invalid_exp[True-False]
6.96s call astropy/io/ascii/tests/test_c_reader.py::test_include_exclude_names[True]
6.78s call astropy/io/ascii/tests/test_c_reader.py::test_not_enough_cols[True]
6.77s call astropy/io/ascii/tests/test_c_reader.py::test_include_names[True]
6.73s call astropy/io/ascii/tests/test_c_reader.py::test_exclude_names[True]
6.41s call astropy/io/ascii/tests/test_c_reader.py::test_lstrip_whitespace[True]
6.13s call astropy/io/ascii/tests/test_c_reader.py::test_fortran_reader[True-False]
6.07s call astropy/io/ascii/tests/test_c_reader.py::test_fortran_reader[True-True]
5.16s call astropy/io/ascii/tests/test_c_reader.py::test_no_header_supplied_names[True]
5.13s call astropy/io/ascii/tests/test_c_reader.py::test_no_header[True]
4.69s call astropy/io/ascii/tests/test_c_reader.py::test_rstrip_whitespace[True]
4.56s call astropy/io/ascii/tests/test_c_reader.py::test_supplied_names[True]
4.53s call astropy/io/ascii/tests/test_c_reader.py::test_comment[True]
4.31s call astropy/io/ascii/tests/test_c_reader.py::test_inf_nan[True]
4.28s call astropy/io/ascii/tests/test_c_reader.py::test_empty_lines[True]
4.28s call astropy/io/ascii/tests/test_c_reader.py::test_many_rows[True]
4.22s call astropy/io/ascii/tests/test_c_reader.py::test_conversion[True]
4.00s call astropy/io/ascii/tests/test_c_reader.py::test_many_columns[True]
3.85s call astropy/io/ascii/tests/test_c_reader.py::test_csv_comment_default[True]
3.80s call astropy/io/ascii/tests/test_c_reader.py::test_strip_line_trailing_whitespace[True]
3.67s call astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-fast_reader2-True]
3.65s call astropy/io/ascii/tests/test_c_reader.py::test_whitespace_before_comment[True]
3.53s call astropy/io/ascii/tests/test_c_reader.py::test_simple_data[True]
3.36s call astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-fast_reader2-False]
3.26s call astropy/io/ascii/tests/test_c_reader.py::test_store_comments[True]
3.21s call astropy/io/ascii/tests/test_c_reader.py::test_default_data_start[True]
3.03s call astropy/io/ascii/tests/test_c_reader.py::test_rdb[True]
2.83s call astropy/io/ascii/tests/test_c_reader.py::test_empty_quotes[True]
2.47s call astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-fast_reader1-True]
2.41s call astropy/io/ascii/tests/test_c_reader.py::test_fast_tab_with_names[True]
2.25s call astropy/io/ascii/tests/test_c_reader.py::test_int_out_of_range[True-True]
2.24s call astropy/io/ascii/tests/test_c_reader.py::test_int_out_of_range[True-False]
2.24s call astropy/io/ascii/tests/test_c_reader.py::test_data_out_of_range[True-fast_reader1-False]
1.32s call astropy/io/ascii/tests/test_c_reader.py::test_fast_reader
1.10s call astropy/io/ascii/tests/test_c_reader.py::test_read_empty_basic_table_with_comments[fast_reader1]
0.69s call astropy/io/ascii/tests/test_c_reader.py::test_many_columns[False]
0.65s call astropy/io/ascii/tests/test_c_reader.py::test_delimiter[False]
0.57s call astropy/io/ascii/tests/test_c_reader.py::test_many_rows[False]
0.35s call astropy/io/ascii/tests/test_c_reader.py::test_conversion[False]
=============================================== 114 passed, 18 skipped, 4 xfailed in 344.31s (0:05:44) ================================================
Activity
pllim commentedon Jan 16, 2020
Is this related to #8858?
astrofrog commentedon Jan 17, 2020
Yes, it is related (though I think we should keep this open separately in case people run into the issue via the test suite)
mwcraig commentedon May 28, 2020
I'm also seeing this a huge slowdown on Windows (python 3.6, 3.7, 3.8) in addition to OSX/python 3.8. Running these tests on azure as part of conda build takes ~2.5 hours on those platforms: sample build
astrofrog commentedon May 28, 2020
@mwcraig - the platforms/Python versions suggest to me that it's also related to #8858 even if the slowdowns are way larger in your case. Have you been able to reproduce such large slowdowns locally?
mwcraig commentedon May 28, 2020
I'll do a couple different local timings and report back; the slowdown is substantial, not sure it is quite as bad as on CI.
astrofrog commentedon May 28, 2020
@taldcroft @dhomeier - I wonder if you have opinions on what we should do here, and whether one of you would have time to investigate this? I still see the C reader tests take minutes to run on MacOSX as described higher up (410 seconds when I tried today!).
Should we try and force the multiprocessing method to be 'fork' on all platforms to avoid this substantial slowdown? (is that even possible on Windows?). Or should we try and re-think the parallelism to avoid using the multiprocessing module and instead using e.g. threading? Or more drastically we could even disable parallel mode on MacOS X with 3.8+ or Windows since it might be counterintuitively slower for users?
saimn commentedon May 28, 2020
Windows has only spawn: https://docs.python.org/3/library/multiprocessing.html#multiprocessing.get_all_start_methods
But I don't understand why that would be that slow:
test_delimiterthat takes 30s has only 3 cols and 2 rows ...CParserpickles the memmap when reading from a file (ref Assess performance of parallel io.ascii reader with 'spawn' multiprocessing method #8858: it might be that the parallel reader is not efficient because it looks like it will pickle the whole contents of the table (via the reduce method). ): https://github.com/astropy/astropy/blob/master/astropy/io/ascii/cparser.pyx#L844 :self.source_ptris used if available, this is the memmap pointer.Then the tests uses a helper function that will read the table 8 times with different options, so for e.g.
test_delimiterthat tests with 5 delimiters that means 5x8 calls to the parallel reader, spawning processes etc.I can reproduce the slownes on Linux by using
multiprocessing.set_start_method('spawn'), e.g.:Since the table is read 40 times, that's 7/40 = 0.175s for one call, which is slow but can be acceptable for a normal use case reading a big table.
Another issue might be that
CParserusesmultiprocessing.cpu_count()processes by default, and it is not clear that on a CI container this will report the good value. It may run more processes than available cores (travis-ci/travis-ci#4696), which can worsen performance.astrofrog commentedon May 28, 2020
@saimn - thanks for investigating! I agree that this is perhaps more a testing issue that in practice might not impact users reading small numbers of big tables. I wondered whether indeed on Azure cpu_count might be very large which could cause the issues @mwcraig was seeing. Maybe we should explicitly be setting the number of processes to e.g. 2 or 4 in the tests rather than relying on cpu_count?
mwcraig commentedon May 28, 2020
The times below are for running the tests as part of
conda build.I'm still waiting for the tests to complete on my local Mac when I have the parallel tests turned on; they've been running for about 1.5 hours now, 12% complete.
With parallel tests turned off the rest ran in 15min, so slow but not as glacial.
mwcraig commentedon May 28, 2020
With the parallel tests turned on, running as part of the test phase of conda build, it took 2:52:32 to run these tests. Perhaps of interest, the last really slow one was
test_fortran_invalid_exp; the remaining after that all ran very quickly (a few seconds).astrofrog commentedon May 28, 2020
Interesting, I wonder what makes it so much slower when part of the conda build, even locally!
mwcraig commentedon May 28, 2020
Not sure, except that perhaps there are multiple levels of subprocessing happening. Will try running the tests not in conda build later today just to confirm the speed issue.
taldcroft commentedon May 28, 2020
I don't have time to investigate this immediately. I agree with @mwcraig that this should not really be a problem in most real-life cases of a huge table where users enable parallel reading. The most immediate impact may just be on testing, which involves relatively small tables but lots of them.
astrofrog commentedon Oct 13, 2020
I think it's still important to try and fix the test suite if we can - we could perhaps skip most but not all of the parallel tests if the spawn method is used?
saimn commentedon Oct 15, 2020
edit: wrong issue