Laurence’s Blog

Following my last two posts (http://blog.entek.org.uk/?p=106 and http://blog.entek.org.uk/?p=112) I took some profilers to my codes.

First up my revised Python implementation:

> python -m cProfile checkmail2
...
         16225093 function calls in 8.663 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    8.663    8.663 :1()
        1    0.000    0.000    0.000    0.000 UserDict.py:17(__getitem__)
        1    5.906    5.906    8.662    8.662 checkmail2:3()
        1    0.000    0.000    8.663    8.663 {execfile}
       37    0.000    0.000    0.000    0.000 {method '__enter__' of 'file' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
       22    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {method 'iteritems' of 'dict' objects}
 16224990    2.755    0.000    2.755    0.000 {method 'startswith' of 'str' objects}
       37    0.001    0.000    0.001    0.000 {open}
        1    0.000    0.000    0.000    0.000 {posix.listdir}

Quite clearly there is a huge number (16 million!) of calls to startswith which is the biggest time-sink outside the main script.

Comparing the Perl implementation:

> perl -d:DProf checkmail3
...
> dprofpp
Total Elapsed Time = 3.426896 Seconds
  User+System Time = 3.401494 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 0.12   0.004  0.007      4   0.0010 0.0016  main::BEGIN
 0.03   0.001  0.001      5   0.0002 0.0002  File::Basename::BEGIN
 0.03   0.001  0.001      1   0.0009 0.0009  warnings::BEGIN
 0.03   0.001  0.001     37   0.0000 0.0000  File::Basename::_strip_trailing_sep
 0.03   0.001  0.001     37   0.0000 0.0000  File::Basename::fileparse
 0.00   0.000  0.002     37   0.0000 0.0000  File::Basename::basename
 0.00   0.000  0.000      1   0.0003 0.0003  File::Glob::doglob
 0.00   0.000  0.000      1   0.0001 0.0001  DynaLoader::dl_load_file
 0.00   0.000  0.000      1   0.0001 0.0003  XSLoader::load
 0.00   0.000  0.000      1   0.0001 0.0001  File::Basename::fileparse_set_fstype
 0.00   0.000  0.000      1   0.0001 0.0001  Exporter::import
 0.00   0.000  0.000      2   0.0000 0.0000  warnings::import
 0.00   0.000  0.000      3   0.0000 0.0000  strict::import
 0.00   0.000  0.000      1   0.0000 0.0003  File::Glob::csh_glob
 0.00   0.000  0.000      1   0.0000 0.0000  strict::bits

Ignoring the actual times which are not directly comparable due to the profiling overheads we can clearly see Perl is benefiting hugely from the inbuilt regex engine as there are 0 function calls associated with each line check.

I did replace the ‘str.startswith’ implementation of the Python script with a version which used ‘re’ regex objects, but this showed even worse performance:

> time python checkmail4
...
python checkmail4 8.42s user 0.33s system 99% cpu 8.765 total


Profiling this one we see the overhead of using ‘re.match’ was about double that of ‘str.startswith’ and, obviously, the number of calls remained the same. On top of this I introduced additional overhead of two calls to ‘re.compile’ at the start of the script, which the profiler showed incurred not insignificant function calls of their own:

> python -m cProfile checkmail4
...
         16225312 function calls in 12.416 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   12.416   12.416 :1()
        1    0.000    0.000    0.000    0.000 UserDict.py:17(__getitem__)
        1    6.662    6.662   12.415   12.415 checkmail4:3()
        2    0.000    0.000    0.000    0.000 re.py:186(compile)
        2    0.000    0.000    0.000    0.000 re.py:227(_compile)
        2    0.000    0.000    0.000    0.000 sre_compile.py:367(_compile_info)
        2    0.000    0.000    0.000    0.000 sre_compile.py:38(_compile)
        4    0.000    0.000    0.000    0.000 sre_compile.py:480(isstring)
        2    0.000    0.000    0.000    0.000 sre_compile.py:486(_code)
        2    0.000    0.000    0.000    0.000 sre_compile.py:501(compile)
       15    0.000    0.000    0.000    0.000 sre_parse.py:144(append)
        2    0.000    0.000    0.000    0.000 sre_parse.py:146(getwidth)
        2    0.000    0.000    0.000    0.000 sre_parse.py:184(__init__)
       21    0.000    0.000    0.000    0.000 sre_parse.py:188(__next)
        2    0.000    0.000    0.000    0.000 sre_parse.py:201(match)
       19    0.000    0.000    0.000    0.000 sre_parse.py:207(get)
        2    0.000    0.000    0.000    0.000 sre_parse.py:307(_parse_sub)
        2    0.000    0.000    0.000    0.000 sre_parse.py:385(_parse)
        2    0.000    0.000    0.000    0.000 sre_parse.py:669(parse)
        2    0.000    0.000    0.000    0.000 sre_parse.py:73(__init__)
        2    0.000    0.000    0.000    0.000 sre_parse.py:96(__init__)
        2    0.000    0.000    0.000    0.000 {_sre.compile}
 16224990    5.751    0.000    5.751    0.000 {built-in method match}
        1    0.000    0.000   12.416   12.416 {execfile}
        6    0.000    0.000    0.000    0.000 {isinstance}
       44    0.000    0.000    0.000    0.000 {len}
       37    0.000    0.000    0.000    0.000 {method '__enter__' of 'file' objects}
       59    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
       24    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        2    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {method 'iteritems' of 'dict' objects}
        4    0.000    0.000    0.000    0.000 {min}
       37    0.002    0.000    0.002    0.000 {open}
       13    0.000    0.000    0.000    0.000 {ord}
        1    0.000    0.000    0.000    0.000 {posix.listdir}

Quite clearly from the profiler output each call to either ‘str.startswith’ or ‘re.match’ use a very small amount of processor time (too small to be output) but the cumulative effect of 16 million calls is where the big slowdown was occurring. To get around this I tried implementing the ‘str.startswith’ version using string splicing (i.e. “line[:5] == ‘From ‘” rather than “line.startswith(‘From ‘)”) and the result was dramatic:

> time python checkmail4
...
python checkmail4 3.86s user 0.31s system 99% cpu 4.186 total


The profiler output for this version shows that the number of function calls is now on a par with the Perl implementation:

> python -m cProfile checkmail4
...
         110 function calls in 4.311 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    4.311    4.311 :1()
        1    0.000    0.000    0.000    0.000 UserDict.py:17(__getitem__)
        1    4.308    4.308    4.311    4.311 checkmail4:3()
        1    0.000    0.000    4.311    4.311 {execfile}
       37    0.000    0.000    0.000    0.000 {method '__enter__' of 'file' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
       29    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {method 'iteritems' of 'dict' objects}
       37    0.003    0.000    0.003    0.000 {open}
        1    0.000    0.000    0.000    0.000 {posix.listdir}

This puts the Python version within 0.6s of the Perl version, which is close enough for me. Especially considering this is effectively comparing Perl to Python on Perl’s hometurf of text matching.

I think Perl would probably still out perform Python if I was wanting to do something more fancy involving regex substitutions but Python’s performance issues, in this case, seem to be purely down to function call overheads which Perl sidesteps by incorporating the regex engine into the core language.

Following my post yesterday I decided to both slightly refine my implementation and see if I could improve the speed of the Python version of my script. All that it really required it a simple search of an mbox file looking for messages with no ‘Status’ header (which is added by mutt when it has seen the message). Both the Perl and Python script I was using yesterday were doing far more than necessary as both (at least partially) parsed the messages which is not required with the mboxes I have. I have therefore re-implemented the Python version as a simple loop over each line in the mbox files which counts the number of items with no status header:

#!/usr/bin/env python

from os import environ, listdir

MAILHOME=environ['HOME'] + '/Mail'

new_mailboxes={}
for file in listdir(MAILHOME):
	no_status=False
	with open('%s/%s' % (MAILHOME, file)) as f:
		for line in f:
			if line.startswith('From '):
				if no_status:
					new_mailboxes[file]=new_mailboxes.get(file, 0) + 1
				no_status=True
			elif line.startswith('Status: '):
				no_status=False
	# Loop ended, make sure we count the last message if we need to.
	if no_status:
		new_mailboxes[file]=new_mailboxes.get(file, 0) + 1

for box, count in new_mailboxes.iteritems():
	print "%s (%d)" % (box, count)

This revised script completes in a much more respectable time, substantially quicker than the original Perl script I was comparing my first attempt to:

> time python checkmail2
...
python checkmail2 5.30s user 0.32s system 99% cpu 5.625 total


Curiosity got the better of me and I implemented the exact same algorithm in Perl and timed that:

#!/usr/bin/env perl

use strict;
use warnings;

use File::Basename;

my %new_mailboxes;
for my $file (glob("$ENV{HOME}/Mail/*")) {
	my $no_status = 0;
	my $basename = basename($file);
	open INPUT, $file;
	while(<INPUT>) {
		if (/^From /) {
			$new_mailboxes{$basename} += 1 if $no_status;
			$no_status = 1;
		} elsif ( /^Status: / ) {
			$no_status = 0;
		}
	}
	close INPUT;
	$new_mailboxes{$basename} += 1 if $no_status;
}

print $_, ' (', $new_mailboxes{$_}, ")\n" for keys(%new_mailboxes);


time perl checkmail3
...
perl checkmail3 2.96s user 0.42s system 97% cpu 3.465 total


Interestingly Perl was still faster by quite some way (the Python version took around 1.6 times as long to run). The question is, is this purely down to the overhead of object-orientated vs procedural or is Perl faster at IO and/or pattern matching (although the Python version should have been quicker here as it was not using a full-blown regex engine to match the start of strings)?

I needed to write a quick script to find which mailboxes in “~/Mail” had unread messages in them. I decided to knock it up in Python, but the script was not performing very well:

> time ./checkmail
...
./checkmail 56.17s user 1.86s system 98% cpu 59.181 total


A quick google found a Perl program which did pretty much the same thing (at http://www.perlmonks.org/?node_id=552218 if you’re interested) which ran, unaltered, on the exact same files performed significantly better:

> time perl checkmail2
...
perl checkmail2 16.66s user 1.27s system 99% cpu 18.043 total


Not only did the Perl version take about 1/3 of the time of the Python implementation but it also counted the number of unread messages and displayed it, while my simple Python script break’d on the first match to avoid needlessly looping over the rest of the messages. The Perl version is managing not to fully decode every message through the use of the Mail::MboxParser library however I could not find a way to achieve the same result in a straightforward manner with the standard Python libraries. Indeed, looking at the documented examples in the python docs, http://docs.python.org/library/mailbox.html#examples, it appears this is the suggested way of doing it (in essence all I need to do is examine the ‘status’ header, the example which uses a very similar loop to just examine the ‘subject’ header).

My Python script is here:

#!/usr/bin/env python

import mailbox
from os import listdir, environ, system

MAILHOME=environ['HOME'] + '/Mail'

new_mail_mailboxes=[]
for file in listdir(MAILHOME):
	for message in mailbox.mbox(MAILHOME + '/' + file):
		if message['status']:
			new_mail_mailboxes.append(file)
			break
print "\n".join(new_mail_mailboxes)