Python multiprocessing text extraction performance issue vs Perl equivalent

Question

Marked this as answered and started a simpler topic around where the speed issue really appear to be

Python slow read performance issue

Thanks for all comments to date, very useful

I have around 40M XML files spread (not evenly) across approx. 60K subdirectories, the structure is based on a 10 digit number split so:

12/34/56/78/90/files.xml

I have a perl script which runs against the files pulling the value of a single field out and prints the value and the filename. The Perl script is wrapped in a bash script which runs max 12 parallel instances across a list of all the directories at depth 2 and then walking down each and processing the files at the bottom level as it finds them.

Taking disk caching out from multiple runs a unix time of the process returns approx:

real    37m47.993s
user    49m50.143s
sys     54m57.570s

I wanted to migrate this to a python script (as a learning exercise and test) so created the following (after a lot of reading up on python methods for various things):

    import glob, os, re
    from multiprocessing import Pool

    regex = re.compile(r'<field name="FIELDNAME">([^<]+)<', re.S)

    def extractField(root, dataFile):
            line = ''
            filesGlob = root + '/*.xml'
            global regex
            for file in glob.glob(filesGlob):
                    with open(file) as x:
                            f = x.read()
                    match = regex.search(f)
                    line += file + '\t' + match.group(1) + '\n'

            dataFile.write(line)

    def processDir(top):
            topName = top.replace("/", "")
            dataFile = open('data/' + topName + '.data', 'w')
            extractField(top, dataFile)
            dataFile.close()

    filesDepth5 = glob.glob('??/??/??/??/??')
    dirsDepth5 = filter(lambda f: os.path.isdir(f), filesDepth5)
    processPool = Pool(12)
    processPool.map(processDir, dirsDepth5)
    processPool.close()
    processPool.join()

But no matter how I slice the content when I run it unix time gives me this kind of result:

real    131m48.731s
user    35m37.102s
sys     48m11.797s

If I run both the python and perl script in a single thread against a small subset (that ends up getting fully cached) so there is no disk io (according to iotop) then the scripts run in almost identical times.

The only conclusion I can think of so far is that the file io is much less efficient in the python script than it is in the perl script as it seems to be io that is causing the issue.

So hopefully that's enough background, my question is am I doing something stupid or missing a trick as I'm running out of ideas but can't believe the io is causing such a difference in processing times.

Appreciate any pointers and will provide more info as/if required.

Thanks

Si

For reference Perl script is below:

use File::Find;

my $cwd = `pwd`;
chomp $cwd;
find( \&hasxml, shift );

sub hasxml {
    if (-d) {
        my @files = <$_/*.xml>;
        if ( scalar(@files) > 0 ) {
            process("$cwd/${File::Find::dir}/$_");
        }
    }
}

sub process {
    my $dir = shift;

    my @files = <$dir/*.xml>;

    foreach my $file (@files) {
        my $fh;
        open( $fh, "< $file" ) or die "Could not read file <$file>";
        my $contents = do { local $/; <$fh> };
        close($fh);
        my ($id) = $contents =~ /<field name="FIELDNAME">([^<]+)<\/field>/s;
        print "$file\t<$id>\n";
    }
}

Answer 1

Depending on the structure of your XML files, you may be able to get some time savings by using mmap. Currently, you're reading in the entire file even though you're only interested in one entry. If your data tends to occur near the top of your files, you can map the file into memory instead of actually reading it in, perform your regex search exactly the same as you already are, and be done with it.

Here is a comparison of the two methods:

I have a text file called "tmp_large.txt" which has 1,000,000 lines in it. Each line has the alphabet in lowercase. In just one line about halfway through the file, I've replaced the letter 'm' with 'x', and I'm searching for that string:

import re
import mmap

from timeit import timeit
from datetime import timedelta

c_regex = re.compile('defghijklxnopqrstuvwx')

def read_file():
    with open('tmp_large.txt', 'r') as fi:
        f = fi.read()
        match = c_regex.search(f)

def mmap_file():
    with open('tmp_large.txt', 'r+b') as fi: # must open as binary for mmap
        mm = mmap.mmap(fi.fileno(), 0)
        match = c_regex.search(mm)
        mm.close()

t1 = timedelta(seconds=timeit(read_file, setup='gc.enable()', number=1))
t2 = timedelta(seconds=timeit(mmap_file, setup='gc.enable()', number=1))

print(t1)
print(t2)

This scenario produces this output:

0:00:00.036021
0:00:00.028974

We see an execution time savings of a bit less than a third. However, if I place the string I'm looking for at the top of the input file, we see this result:

0:00:00.009327
0:00:00.000338

Obviously both methods are faster, but the time savings is much more significant for the memory mapped method.

Since I don't know the structure of your data or how large your files are, you may see less dramatic results from this. But as long as the data you're seeking isn't at the end of your target files, you'll probably see a bit of an improvement from memory mapping your files, since it will avoid bringing data into memory that you don't actually end up using.

As a side note, I also tried iterating over lines in a file until we hit a line that matched the regex, but it was too slow to bother including here. Also, I did confirm that the regex was actually matching in my example, but I removed the print code and results for brevity

As suggested in the comments, using the iterator iglob and replacing map with something like apply_async may help speed things up too, because they would both help reduce your memory footprint:

processPool = Pool(12)

for dir_or_file in glob.iglob('??/??/??/??/??'):
    if os.path.isdir(dir_or_file):
        processPool.apply_async(processDir, (dir_or_file,))

processPool.close()
processPool.join()

This approach would also allow your subprocesses to get started on processing the first files while you're still identifying the rest.

A few other code notes for you:

1. You don't need the re.S flag on your regex since you don't actually have any '.' in the regex pattern.
2. Unless you have some compelling reason not to, you should open your output file with the with open() construct the same way you're opening your input files to prevent stray open file descriptors if you have an exception.
3. When you're calculating the dataFile and filesGlob, consider using os.path.join() instead of manually adding in the path separators. It'll be less error-prone in the long run.
4. You don't need your global regex line. You can always read and call methods of global objects without it, just like my example does. You only need it when you are going to modify a global.
5. Just in case you're not aware of it, mutliprocessing pools will, by default, only launch as many workers as you have CPU cores. If you already knew that, please ignore this comment. Specifying 12 processes for your pool just seemed a bit odd to me.

Answer 2

EDIT

Forgot to add thanks to the contributors on this thread:

Python slow read performance issue

who helped me solve this.

EDIT

It all boiled down in the end to the order of the directory read, this applied to my main application as well as the tests.

Basically Perl sorts lexographically (i.e. 1,11,2,22) by default, Python sorts by directory order (ls -U) and the files are created in a natural order (1,2,3,4) so I took the original Python slurp and created a slurpNatural after some searching Stackoverflow for a simple natural sort:

import glob, sys, re

def natural_sort_key(s, _nsre=re.compile('([0-9]+)')):
    return [int(text) if text.isdigit() else text.lower()
            for text in re.split(_nsre, s)]

for file in sorted(glob.iglob(sys.argv[1] + '/*.xml'), key=natural_sort_key):
    with open(file) as x:
        f = x.read()

I then ran all 3 against the 50K docs and got:

$ sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches'
$ /usr/bin/time perl slurp.pl 1
1.21user 2.17system 0:12.70elapsed 26%CPU (0avgtext+0avgdata 9140maxresident)k
1234192inputs+0outputs (22major+2466minor)pagefaults 0swaps

$ sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches'
$ /usr/bin/time python slurp.py 1
2.88user 6.13system 4:48.00elapsed 3%CPU (0avgtext+0avgdata 8020maxresident)k
1236304inputs+0outputs (35major+52252minor)pagefaults 0swaps

$ sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches'
$ /usr/bin/time python slurpNatural.py 1
1.25user 2.82system 0:10.70elapsed 38%CPU (0avgtext+0avgdata 22408maxresident)k
1237360inputs+0outputs (35major+56531minor)pagefaults 0swaps

The natural sort which mirrors the creation order is clearly the fastest and in this case mirrors how my actual data is created and so have now changed the Python to sort the directory contents before processing.

Thanks for all the help, I honestly didn't think the order of reading the files would make such a big difference!

Si