Assess performance of parallel io.ascii reader with 'spawn' multiprocessing method

Based on my understanding of the fast C reader after the work I did in #8853, currently when using the multiprocessing 'spawn' method, 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). This would mean memory mapping isn't used. So this issue is a reminder that we should check if this is indeed the case. If so, we might want to consider passing the filename to sub-processes rather than the memory mapped bytes string.

And from the other thread, if I understood correctly, performance might also be OS-dependent?

By default yes, but on Linux or Mac one can easily test both multiprocessing start methods (see #8851 for some example code)

@taldcroft

I finally had a chance to crunch some numbers with a simple CSV table with 10^4 to 10^7 lines - this is on MacOS X with Python 3.8 so with the spawn method:

In [1]: with open('large_ascii.csv', 'w') as f:
   ...:     for line in range(10000):
   ...:         f.write('1,3.2,banana,3.441\n')
   ...: 

In [2]: from astropy.io import ascii
   ...: 

In [3]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False, fast_reader={'parallel': False, 'use_fast_converter': True})
   ...: 
5.82 ms ± 636 µs per loop (mean ± std. dev. of 7 runs, 100 loops each)

In [4]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False, fast_reader={'parallel': True, 'use_fast_converter': True})
   ...: 
933 ms ± 70.7 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

In [5]: with open('large_ascii.csv', 'w') as f:
   ...:     for line in range(100000):
   ...:         f.write('1,3.2,banana,3.441\n')
   ...: 

In [6]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False, fast_reader={'parallel': False, 'use_fast_converter': True})
   ...: 
57.1 ms ± 6.09 ms per loop (mean ± std. dev. of 7 runs, 10 loops each)

In [7]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False, fast_reader={'parallel': True, 'use_fast_converter': True})
   ...: 
940 ms ± 27.8 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

In [8]: with open('large_ascii.csv', 'w') as f:
   ...:     for line in range(1000000):
   ...:         f.write('1,3.2,banana,3.441\n')
   ...: 

In [9]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False, fast_reader={'parallel': False, 'use_fast_converter': True})
   ...: 
592 ms ± 65.7 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

In [10]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False, fast_reader={'parallel': True, 'use_fast_converter': True})
    ...: 
2.39 s ± 45.8 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

In [11]: with open('large_ascii.csv', 'w') as f:
    ...:     for line in range(10000000):
    ...:         f.write('1,3.2,banana,3.441\n')
    ...: 

In [12]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False, fast_reader={'parallel': False, 'use_fast_converter': True})
5.21 s ± 56 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

In [13]: 

In [13]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False, fast_reader={'parallel': True, 'use_fast_converter': True})
    ...: 
19.7 s ± 2.91 s per loop (mean ± std. dev. of 7 runs, 1 loop each)

For small tables the performance is 100 times worse for the parallel build which I guessed might happen since there is going to be an overhead of spawning the processes. However, even for 10^7 lines the parallel performance is worse, so there is more than just process spawning going on, I think it is related to the memory map being pickled. The time for the parallel mode basically seems to maybe converge to roughly N times more than the serial one where N is the number of processes (note that the default on my machine is 4 processes, so changing to 2 below):

In [14]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False, fast_reader={'parallel': 2, 'use_fast_converter': True})
15.1 s ± 135 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

Based on this, I would suggest that we should force the 'fork' mode to be used which then means disabling parallel mode on Windows, but I think that's reasonable since there is no reason someone would use the parallel mode on Windows. To avoid breaking scripts I'm not suggesting raising an error on Windows, just emitting a warning that the reader is falling back to non-parallel mode.

@taldcroft - what do you think?

Also cc-ing @saimn and @mwcraig who were discussing this issue in #9864.

To be clear, if someone can fix the reader to be more efficient in spawn mode, then that is preferable, but until then I think we would do users a service and speed up our test suite by falling back to serial mode instead of using the spawn mode.

I think removing support for spawn will also allow us to remove some of the code in the cython code, and removing code is always nice 😄

Really surprising ! The cost of spawning processes should be constant, whereas here the overhead scales with the number of lines, there is clearly something wrong. How many processes ? And would be interesting to have the timings with fork as well.

The cost of spawn is ~5ms for me (for 4 processes):

❯ python test.py fork 1_000
..........
 0.002246189117431641
❯ python test.py spawn 1_000    
..........
 0.007513070106506347
❯ python test.py fork 100_000  
..........
 0.0173797607421875
❯ python test.py spawn 100_000  
..........
 0.022875523567199706
❯ python test.py fork 1_000_000
..........
 0.14745426177978516
❯ python test.py spawn 1_000_000
..........
 0.1520008325576782

import math
import multiprocessing
import sys
import time


def run(size):
    pool = multiprocessing.Pool()
    data = list(range(size))

    t = time.time()
    for _ in range(10):
        print('.', end='', flush=True)
        pool.map(math.sqrt, data)
    print('\n', (time.time() - t) / 10)


if __name__ == '__main__':
    method, size = sys.argv[1:]
    multiprocessing.set_start_method(method)
    run(int(size))

Are we sure the parallel mode actually works ?

In [1]: In [1]: with open('large_ascii.csv', 'w') as f:
   ...:    ...:     for line in range(10000):
   ...:    ...:         f.write('1,3.2,banana,3.441\n')
   ...: 

In [2]: from astropy.io import ascii

In [3]: In [3]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False,
   ...:  fast_reader={'parallel': False, 'use_fast_converter': True})
4.65 ms ± 252 µs per loop (mean ± std. dev. of 7 runs, 100 loops each)

In [4]: In [4]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False,
   ...:  fast_reader={'parallel': True, 'use_fast_converter': True})
27 ms ± 3 ms per loop (mean ± std. dev. of 7 runs, 10 loops each)

In [5]: In [5]: with open('large_ascii.csv', 'w') as f:
   ...:    ...:     for line in range(100000):
   ...:    ...:         f.write('1,3.2,banana,3.441\n')
   ...:    ...:
   ...: 

In [6]: In [6]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False,
   ...:  fast_reader={'parallel': False, 'use_fast_converter': True})
48.6 ms ± 2.85 ms per loop (mean ± std. dev. of 7 runs, 10 loops each)

In [7]: In [7]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False,
   ...:  fast_reader={'parallel': True, 'use_fast_converter': True})
152 ms ± 3.3 ms per loop (mean ± std. dev. of 7 runs, 10 loops each)

In [8]: In [8]: with open('large_ascii.csv', 'w') as f:
   ...:    ...:     for line in range(1000000):
   ...:    ...:         f.write('1,3.2,banana,3.441\n')
   ...: 

In [9]: In [9]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=False,
   ...:  fast_reader={'parallel': False, 'use_fast_converter': True})
445 ms ± 12.2 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

In [10]: In [10]: %timeit ascii.read('large_ascii.csv', format='csv', delimiter=',', guess=Fals
    ...: e, fast_reader={'parallel': True, 'use_fast_converter': True})

1.42 s ± 14.7 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

At the time it was written, it definitely provided performance gains. See near the bottom of https://docs.astropy.org/en/latest/io/ascii/fast_ascii_io.html#speed-gains and in particular http://mdmueller.github.io/ascii-profiling/.

But now, on both Mac and linux, I can't see anything but at least a factor of 4 reduction in performance using parallel. This holds even with multiprocessing.set_start_method('fork', force=True). (IIRC, the force=True seems to be undocumented but I had to use that in order to get sherpa to work with Python 3.8 on Mac). The factor of 4 also holds for Python 3.7 where fork is the default.

There is one open question whether pickling is part of the issue and if pickle protocol 5 (https://www.python.org/dev/peps/pep-0574/) helps at all. I don't have time before the 4.2 feature freeze to spend on this, however.

Takeaway, I don't know what changed, but based on what we are all seeing here it seems like disabling (ignoring) the parallel option on all platforms is the right thing to do now.

BTW, I did my own performance testing using all float values. The documentation states that the performance gains are reduced for data files with integers and repeated strings.

Yes I think disabling the option and removing the parallel code would be the right thing to do, including backporting it to LTS since it is essentially a bug that it doesn't work. Ok the plus side we can do it in a way that won't break things for users (if anything it will speed it up!)

I'm on the fence about actually removing the code immediately. It used to provide a performance gain, so maybe someone can figure out what has gone wrong. That will be harder if the code has actually been taken out. Perhaps we can wait a release before removing it, and in the meantime just ignore the option (but issue a warning for parallel=True).

Sounds good. We might want to open an issue about removing the code if not fixed and milestone for eg 4.3 so that we don't forget. In the meantime a minimal PR ignoring the option could be backported to 4.0.x and 4.1.x.

@taldcroft

@taldcroft just to check and to avoid duplication of effort are you planning on doing the pr to ignore option?

Yeah the code seems broken, and I would bet since the Python 3 transition. E.g. the comparison self.source[index] != '\n' does not work, which explains why it runs only one process with a big chunk. But even fixing that does not help.

astropy/astropy/io/ascii/cparser.pyx

Line 446 in 88b6bd4

while index < source_len and self.source[index] != '\n':

@taldcroft

@taldcroft just to check and to avoid duplication of effort are you planning on doing the pr to ignore option?

Not if there are other people willing. I have a number of other deadlines next week before the code freeze.

See #10880

Closing this issue in favor of #10880 and #10882 (the original issue here was assessement of performance which is done)

Navigation Menu

Repository navigation

Assess performance of parallel io.ascii reader with 'spawn' multiprocessing method #8858

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Assess performance of parallel io.ascii reader with 'spawn' multiprocessing method #8858

Description

Activity

pllim commented on Jun 17, 2019

astrofrog commented on Jun 17, 2019

astrofrog commented on Oct 14, 2020

astrofrog commented on Oct 14, 2020

astrofrog commented on Oct 14, 2020

saimn commented on Oct 15, 2020

saimn commented on Oct 15, 2020

saimn commented on Oct 15, 2020

taldcroft commented on Oct 15, 2020

taldcroft commented on Oct 15, 2020

astrofrog commented on Oct 15, 2020

taldcroft commented on Oct 15, 2020

astrofrog commented on Oct 15, 2020

astrofrog commented on Oct 15, 2020

saimn commented on Oct 15, 2020

taldcroft commented on Oct 15, 2020

astrofrog commented on Oct 16, 2020

astrofrog commented on Oct 16, 2020

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions