Profiling your Python code

Python provides support for deterministic profiling of your application. It's very easy to setup and use. To start profiling your code, two python modules are used:

•  cProfile - the application that collects profiling data
• pstats - the application that makes the profling data human readable
  

You can read more about Python profiling stuff at The Python Profilers page.

I'll show an example of how you can use the profiler.

Say I need to calculate the sum of all odd numbers from zero to an arbitrary positive value. My initial code might end up something like this:

def odd_numbers(max):
    """ Returns a list with all odd numbers between 0 to max (inclusive) """
    l = list()
    for i in xrange(max+1):
        if (i & 1):
            l.append(i)
    return l

def sum_odd_numbers(max):
    """ Sum all odd numbers between 0 to max (inclusive) """
    odd_nbrs = odd_numbers(max)

    res = 0
    for odd in odd_nbrs:
        res += odd
    return res

def main():
    # Run this 100 times to make it measurable
    for i in xrange(100):
        print sum_odd_numbers(1024)

if __name__ == '__main__':
    main()

Now I want to find out where my code spend most if its time to help me optimize the code if possible. To profile this snippet I run:

$ python -m cProfile sum_odd.py

This will output some statistics about the code (try it), but I'll show you a more handy way to browse and examine the profile dump.

$ python -m cProfile -o profile_dump sum_odd.py

This will output the profiling statistics to a file (in non-human readable format) which can be loaded and examined with pstats. Start pstats and browse the profile dump:

$ python -m pstats
Welcome to the profile statistics browser.                    
% help                                                        

Documented commands (type help topic):
========================================
EOF  add  callees  callers  quit  read  reverse  sort  stats  strip

Undocumented commands:
======================
help

% read profile_dump
profile_dump% stats
Tue Dec  8 20:55:41 2009    profile_dump

         51405 function calls in 0.186 CPU seconds

   Random listing order was used

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    51200    0.082    0.000    0.082    0.000 {method 'append' of 'list' objects}
      100    0.099    0.001    0.181    0.002 main.py:1(odd_numbers)
        1    0.000    0.000    0.185    0.185 main.py:1(module)
        1    0.000    0.000    0.186    0.186 {execfile}
      100    0.004    0.000    0.184    0.002 main.py:9(sum_odd_numbers)
        1    0.000    0.000    0.186    0.186 string:1(module)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.001    0.001    0.185    0.185 main.py:18(main)


profile_dump%

This will of course give the same information as if you just executed cProfile without specifying an output file. The advantage of using pstats interactively is that you can view the data in different ways.

Now I want to find out in which function we spend most time. This can be done by using the sort command:

profile_dump% sort
Valid sort keys (unique prefixes are accepted):
stdname -- standard name
nfl -- name/file/line
pcalls -- call count
file -- file name
calls -- call count
time -- internal time
line -- line number
cumulative -- cumulative time
module -- file name
name -- function name
profile_dump% sort time
profile_dump% stats
Tue Dec  8 20:55:41 2009    profile_dump

         51405 function calls in 0.186 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      100    0.099    0.001    0.181    0.002 main.py:1(odd_numbers)
    51200    0.082    0.000    0.082    0.000 {method 'append' of 'list' objects}
      100    0.004    0.000    0.184    0.002 main.py:9(sum_odd_numbers)
        1    0.001    0.001    0.185    0.185 main.py:18(main)
        1    0.000    0.000    0.186    0.186 {execfile}
        1    0.000    0.000    0.185    0.185 main.py:1(module)
        1    0.000    0.000    0.186    0.186 string:1(module)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Nice! We can see that most time is spent in the odd_numbers function. The time key specifies that we would like to sort the data by the time spent in a function (exclusive calls to other functions).

Time to optimize, change the odd_numbers function to the following snippet:

def odd_numbers(max):
    """ Returns a list with all odd numbers between 0 to max (inclusive) """
    return [i for i in xrange(max+1) if (i & 1)]

Now profile the code and load the dump in pstats:

profile_dump% stats
Tue Dec  8 21:20:19 2009    profile_dump

         205 function calls in 0.020 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      100    0.015    0.000    0.015    0.000 main.py:1(odd_numbers)
      100    0.004    0.000    0.019    0.000 main.py:5(sum_odd_numbers)
        1    0.001    0.001    0.020    0.020 main.py:14(main)
        1    0.000    0.000    0.020    0.020 {execfile}
        1    0.000    0.000    0.020    0.020 main.py:1(module)
        1    0.000    0.000    0.020    0.020 string:1(module)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Wow! Not that bad, we decreased the number of function calls from 51405 to 205. We also decreased the total time spent in the application from 0.186 to 0.020 CPU seconds by writting proper Python code :)

FUSE - Filesystem in Userspace part 3 (final)

Finally, as I promised, the last blog post on implementing file systems using FUSE.

I've created a file system, shoutcastfs, which enables you to mount the Shoutcast Radio directory as a file system. The genres are represented as directories and stations as files. Each file contains the station's playlist and the files are suffixed with .pls which makes it possible to load the playlist in a media player such as Amarok by double-clicking the file.

Of course, I'm using pyshoutcast (Python shoutcast API) to access the shoutcast service.

#!/usr/bin/env python
# -*- coding: utf-8 -*-
import errno
import fuse
import stat
import os
import shoutcast

fuse.fuse_python_api = (0, 2)

_shoutcastApi = shoutcast.ShoutCast()

class RootInfo(fuse.Stat):
    def __init__(self):
        fuse.Stat.__init__(self)
        self.st_mode = stat.S_IFDIR | 0755
        self.st_nlink = 2
        self._genres = {}

    @property
    def genres(self):
        if not self._genres:
            for g in _shoutcastApi.genres():
                self._genres[g] = GenreInfo(g)
        return self._genres

class GenreInfo(fuse.Stat):
    def __init__(self, name):
        fuse.Stat.__init__(self)
        self.st_mode = stat.S_IFDIR | 0755
        self.st_nlink = 2
        self.name = name
        self._stations = {}

    @property
    def stations(self):
        if not self._stations:
            for s in _shoutcastApi.stations(self.name):
                name = '{0}.pls'.format(s[0])
                name = name.replace('/', '|')
                self._stations[name] = StationInfo(name, s[1])
        return self._stations

class StationInfo(fuse.Stat):
    def __init__(self, name, station_id):
        fuse.Stat.__init__(self)
        self.st_mode = stat.S_IFREG | 0644
        self.st_nlink = 1
        # Hope no playlist exceeds this size
        self.st_size = 4096
        self.name = name
        self.station_id = station_id
        self._content = None

    @property
    def content(self):
        if self._content is None:
            self._content = _shoutcastApi.tune_in(self.station_id).read()
        return self._content

class ShoutcastFS(fuse.Fuse):
    def __init__(self, *args, **kw):
        fuse.Fuse.__init__(self, *args, **kw)
        self.root = RootInfo()

    def split_path(self, path):
        """ Returns genre and station """
        if path == '/':
            return (None, None)

        parts = path.split('/')[1:]
        if len(parts) == 1:
            return (parts[0], None)
        else:
            return parts

    def getattr(self, path):
        genre, station = self.split_path(path)

        if genre is None:
            stat = self.root
        else:
            stat = self.root.genres.get(genre)
            if not stat:
                return -errno.ENOENT

            if station:
                stat = stat.stations.get(station)
                if not stat:
                    return -errno.ENOENT
        return stat

    def readdir(self, path, offset):
        yield fuse.Direntry('.')
        yield fuse.Direntry('..')

        if path == '/':
            entries = self.root.genres.keys()
        else:
            entries = self.root.genres[path[1:]].stations.keys()

        for e in entries:
            yield fuse.Direntry(e)

    def open(self, path, flags):
        # Only support for 'READ ONLY' flag
        access_flags = os.O_RDONLY | os.O_WRONLY | os.O_RDWR
        if flags & access_flags != os.O_RDONLY:
            return -errno.EACCES
        else:
            return 0

    def read(self, path, size, offset):
        genre, station = self.split_path(path)
        info = self.root.genres[genre].stations[station]
        if offset < info.st_size:
            if offset + size > info.st_size:
                size = info.st_size - offset
            return info.content[offset:offset+size]
        else:
            return ''

if __name__ == '__main__':
    fs = ShoutcastFS()
    fs.parse(errex=1)
    fs.multithreaded = False
    fs.main()

To try the file system, run:

$ # Download shoutcast.py
$ wget http://github.com/mariob/pyshoutcast/raw/master/src/shoutcast.py
$ mkdir mnt
$ ./shoutcastfs mnt
$ cd mnt/
$ ls
...A list of genres...
$ cd Samba
$ ls
...A list of 'Samba' stations...
$ cat [station name]
...Playlist data...

Have fun!

Fedora 12

For the moment I'm evaluating Fedora 12. I was a bit disappointed on the Kubuntu 9.10 release, the distribution felt a little bit slow and tiered. The only thing I'm satisfied with is the boot time, it starts quite fast.

The KDE4 desktop in Fedora feels kind of snappier than KDE in Kubuntu. I'm not sure if it's because Fedora is compiled for i686 and not i386 or if the team have done any optimizations. I didn't enabled desktop effects in neither distribution. I installed the nvidia proprietary driver in Kubuntu but use Nouveau (open source driver) in Fedora. I might try the proprietary driver in Fedora to see if I gain any speed.

There's one bad thing I found in Fedora in comparision with Kubuntu, KPackageKit. It takes ages before starting compared to the Kubuntu version so I'm using yum from the shell prompt instead. Well, to be honest, I'm not a heavy user of UI front-ends to package management systems. In Kubuntu I prefer using aptitude instead of KPackageKit.

I think I'll give Fedora a chance and try it out for a while.