I’ve recently been tweaking my server setup for a Django 1.3 web site with the goal of making it a bit faster. Of course, there is a lot of speed to gain by improving e.g. the number of database queries needed to render a web page, but the server setup also has an effect on the web site performance. This is a log of my findings.

All measurements have been done using the ab tool from Apache using the arguments -n 200 -c 20, which means that each case have been tested with 20 concurrent requests up to 200 requests in total. The tests was run from another machine than the web server, with around 45ms RTT to the server. This is not a scientific measurement, but good enough to let me quickly test my assumptions on what increases or decreases performance.

The Django app isn’t particularly optimized in itself, so I don’t care much about the low number of requests per second (req/s) that it manages to process. The main point here is the relative improvement with each change to the server setup.

The baseline setup is a Linode 1024 VPS (Referral link: I get USD 20 off my bill if you sign up and remain a customer for 90 days), running Apache 2.2.14 with mpm-itk, mod_wsgi in daemon mode with maximum 50 threads and restart every 10000 requests, SSL using mod_ssl, and PostgreSQL 8.4.8 as the database. For the given Django app and hardware, this setup is strolling along at 4.0 req/s.

With this blog post as reference, I switched from Apache+mod_wsgi to using nginx 0.7.5 as SSL terminator, for serving static media, and as a proxy in front of Gunicorn 0.13.4. Gunicorn is a WSGI HTTP server, hosting the Django site. The Linode VPS got access to four CPU cores (n=4), so I set up nginx with 4 workers (n) and Gunicorn with 9 workers (2n+1). Different values for these settings are sometimes recommended, but this is what I’m currently using. This setup resulted in an increase to 9.0 req/s.

A nice improvement, but I changed multiple components here, so I don’t know exactly what helped. It would be interesting to test e.g. Apache with mod_proxy in front of Gunicorn, as well as different number of nginx and Gunicorn workers. The nginx version is also a bit old, because I used the one packaged in Ubuntu 10.04 LTS. I should give nginx 1.0.x a spin.

Next up, I added pgbouncer 1.3.1 (as packaged in Ubuntu 10.04 LTS, latest is 1.4.2) as a PostgreSQL connection pooler. I let pgbouncer do session pooling, which is the safest choice and the default. Then I changed the Django app settings to use pgbouncer at port 6432, instead of connecting directly to PostgreSQL’s port 5432. This increased the performance further to 10.5 req/s.

Then, I started looking at SSL performance, without this being the bottleneck at all. I learned a lot about SSL performance, but didn’t improve the test results at all. Some key points was:

• nginx defaults to offering Diffie-Hellman Ephemeral (DHE) which takes a lot of resources. Notably, the SSL terminators stud and stunnel does not use DHE. See this blog post for more details and how to turn off DHE in nginx.

• If you’re using AES, you can process five times as many requests with a 1024 bit key compared to a 2048 bit key. I use a 2048 bit key.

• 64-bit OS and userland doubles the connections per second compared to 32-bit. My VPS is stuck at 32-bit for historical reasons.

• SSL session reuse eliminates one round-trip for subsequent connections. I set this up, but my test setup only use fresh connections, so this improvement isn’t visible in the test results.

• Browsers will go a long way to get hold of missing certificates in the certificate chain between known CA certificates and the site’s certificate. To avoid having the browser doing requests to other sites to find missing certificates, make sure all certificates in the chain are provided by your server.

  If you’re switching from Apache to Nginx, note that Apache uses separate files for your SSL certificate and the SSL certificate chain, while Nginx wants these two files to be concatenated to a single file, with your SSL certificate first.

Next, I read about transaction management and the use of autocommit in Django. The Django site I’m testing is read-heavy, with almost no database writes at all. It doesn’t use Django’s transaction middleware, which means that each select/update/insert happens in its own transaction instead of having one database transaction spanning the entire Django view function.

Since I’m using PostgreSQL >= 8.2, which supports INSERT ... RETURNING, I can turn on autocommit in the Django settings, and keep the transaction semantics of a default Django setup without the transaction middleware. Turning on autocommit makes PostgreSQL wrap each query with a transaction, instead of Django adding explicit BEGIN, and COMMIT or ROLLBACK statements around each and every query. Somewhat surprisingly, this reduced the performance to 9.2 req/s. Explanations as to why this reduced the performance are welcome.

Reverting the autocommit change, I got back to 10.5 req/s. Then I tried tuning the PostgreSQL configuration using the pgtune tool. I went for the web profile, with autodetection of the amount of memory (1024 MB):

pgtune -i /etc/postgresql/8.4/main/postgresql.conf -o postgresql-tuned.conf -T Web
mv postgresql-tuned.conf /etc/postgresql/8.4/main/postgresql.conf

pgtune changed the following settings:

maintenance_work_mem = 60MB        # From default 16MB
checkpoint_completion_target = 0.7 # From default 0.5
effective_cache_size = 704MB       # From default 128MB
work_mem = 5MB                     # From default 1MB
wal_buffers = 4MB                  # From default 64kB
checkpoint_segments = 8            # From default 3
shared_buffers = 240MB             # From default 28MB
max_connections = 200              # From default 100

After restarting PostgreSQL with the updated settings, the performance increased to 11.7 req/s.

To summarize: in a few hours, I’ve learned a lot about SSL performance tuning, and–without touching any application code–I’ve almost tripled the amount of requests that the site can handle. The performance still isn’t great, but it’s a lot better than what I started with, and the setup is still far from perfect.

To get further speed improvements, I would mainly look into three areas: adding page (or block) caching where appropriate, log database queries and tweak the numerous or slow ones, and look further into tweaking the PostgreSQL settings. But, that’s for another time.

If you have suggestions for other server setup tweaks, please share them in the comments, and I’ll try them out.

Updated: Removed the “mean response time” numbers, which simply is (time of full test run) / (number of requests). It just told us the same as req/s in a less intuitive way. The other interesting number here is the perceived latency for a single user/request. I’ll make sure to include it in future posts.

In Pykka 0.13–which was released almost two weeks ago–traversing the attributes of an actor is about 8.3 times faster than it used to be. To paraphrase Apple: “8.3X faster. That’s amazing!” (Update: This was written a couple of hours before the news of Jobs’ passing arrived. May he continue to inspire us.)

So, what is “traversable attributes”? Let’s take a few steps back.

If we were a conservative actor adhering strictly to the actor model, we surely wouldn’t share our attributes with anybody else. We would expect other actors to send serializable messages to us, asking nicely to get the value of the attribute, or maybe asking for something else. Of course, the other actors wouldn’t even know the attribute existed unless we told them, and even then they wouldn’t ever dream of requesting a reference to our attribute or altering the attribute directly. It would be indecent. It would break the rules of the actor model. It would be unsafe.

When using Pykka, you can keep to the traditional way of passing messages back and forth between the actors. You start the actor by calling the Actor.start() class method, which returns an ActorRef object. This object can safely be passed around and even shared between threads. The ActorRef object got two methods for sending messages to the actor, called send_one_way() and send_request_reply(). This is nice enough by itself, and it gives you a way to build concurrent applications which is easier to reason about–just as promised by advocates of the actor model–than when you do the thread and lock management dance. You can quickly hack together a simple actor implementation like this from scratch for each and every application you make using e.g. Thread and Queue. I’ve done this a couple of times, and it works.

But, I wanted a bit more, so I created Pykka.

First, I wanted to get rid of verbose dict messages all over my code base. I just wanted to call regular methods and access regular attributes on regular objects. Pykka provides a safe way of doing this, called ActorProxy. An ActorProxy is nothing more than a wrapper around an ActorRef. It does all it’s magic by sending messages to the actor, just like you used to do yourself.

from pykka.actor import ThreadingActor

class X(ThreadingActor):
    y = 1

>>> x = X.start().proxy()
>>> x.y.get()
1
>>> x.stop()

Second, I wanted to be able to organize actors like regular code, e.g. by splitting them into multiple classes. Imagine a running actor a which have the attribute b. The “subobject” b have the method c().

from pykka.actor import ThreadingActor

class B(object):
    def c(self):
        return 1 + 1

class A(ThreadingActor):
    b = B()

If you call a.b.c(), the following happens:

1. We send a message to actor a requesting attribute b, and immediately get a future object back which is our handle to the result which will be available in the future.

2. Actor a gets the message, looks up attribute b, and returns a copy of the object referenced by the b attribute.

3. We call c() on the future, but the Future class doesn’t have an attribute called c, so it fails. Alternatively, we use the future correctly and call get() on the future to get the real result, a copy of b. Then we call c() on the copy of b. The method c() is now running, but it is running in the caller’s thread, and not in the actor a like I wanted it to do.

>>> a = A.start().proxy()
>>> a.b.c()
AttributeError: 'ThreadingFuture' object has no attribute 'c'
>>> a.b.get().c()
2   # Result calculated in the caller's thread
>>> a.stop()

The simple attribute access that the ActorProxy provides isn’t enough to make this work.

To make the a.b.c() method call be executed in the actor a instead of the caller’s thread, we need to traverse attribute b without having it returned to us, so that we can get to c() while still inside the actor a, and call its method c(). We need what we in Pykka call traversable attributes.

To make an attribute traversable, the only thing we need to do is to mark it as such by adding the attribute pykka_traversable to the traversable attribute:

from pykka.actor import ThreadingActor

class B(object):
    pykka_traversable = True
    def c(self):
        return 1 + 1

class A(ThreadingActor):
    b = B()

>>> a = A.start().proxy()
>>> a.b.c().get()
2   # Result calculated by the actor `a`
>>> a.stop()

When you access a regular attribute of a Pykka actor, you just get a future object, which, when you call get() on it, will return a copy of the attribute. When you access a traversable attribute of a Pykka actor, you get a brand new ActorProxy which wraps the same ActorRef, but method calls and attribute accesses on the new proxy object will work on the actor’s attribute instead of the actor itself.

Speeding up access to traversible attributes

If you’re still following, you’re maybe wondering how we sped up access to traversable attributes with a factor of 8.3. The answer is a few lines up: “you get a brand new ActorProxy.”

So, why should that matter?

If you split your actor into multiple classes using traversable attributes, you’re probably going to use each traversable attribute more than once. Maybe really often. Turns out, creating brand new ActorProxy objects for the same attribute over and over again is kind of wasteful.

How did you find out?

John Bäckstrand was irritated by Mopidy being almost unusable on his slow system, and attacked the problem in the scientific way: by measuring where the bottleneck was. John quickly pointed out that access to second-level attributes, which required the traversal of a traversable attribute, was five times slower than access to first-level attributes, which didn’t involve traversable attributes. This observation made it obvious that the creation of new ActorProxy objects whenever we accessed traversable attributes–even though the proxy objects didn’t contain any state and was fully reusable–probably needed refinement.

To be sure we fixed the issue, we started by writing a performance test which compared attribute access with and without the traversal of a traversable attribute.

# Using Pykka 0.12.4
test_direct_plain_attribute_access took 0.958s
test_direct_callable_attribute_access took 0.977s
test_traversible_plain_attribute_access took 8.259s
test_traversible_callable_attribute_access took 8.344s

Then, the fix was short and easy: Cache and reuse ActorProxy objects.

diff --git a/pykka/proxy.py b/pykka/proxy.py
index 27c075b..4c6b908 100644
--- a/pykka/proxy.py
+++ b/pykka/proxy.py
@@ -58,6 +58,7 @@ class ActorProxy(object):
         self.actor_ref = actor_ref
         self._attr_path = attr_path or tuple()
         self._known_attrs = None
+        self._actor_proxies = {}
 
     def _update_attrs(self):
         self._known_attrs = self.actor_ref.send_request_reply(
@@ -88,7 +89,10 @@ class ActorProxy(object):
         if attr_info['callable']:
             return _CallableProxy(self.actor_ref, attr_path)
         elif attr_info['traversable']:
-            return ActorProxy(self.actor_ref, attr_path)
+            if attr_path not in self._actor_proxies:
+                self._actor_proxies[attr_path] = ActorProxy(
+                    self.actor_ref, attr_path)
+            return self._actor_proxies[attr_path]
         else:
             message = {
                 'command': 'pykka_getattr',

The result was immediate: The performance test for traversable attribute access showed an 8.3X improvement.

# Using Pykka 0.13
test_direct_plain_attribute_access took 0.953s
test_direct_callable_attribute_access took 0.988s
test_traversible_plain_attribute_access took 0.984s
test_traversible_callable_attribute_access took 1.006s

Mopidy use Pykka’s traversable attributes heavily to organize its backend code. Obviously, we try to avoid wiring up lots of actors in Mopidy’s unit tests, but we’ve been lazy and use some actors in the tests. These five lines of code inserted at the right place in a dependency made Mopidy’s test suite run 20% faster, and made John’s use case run 166% faster.

We could use more of five-line patches like that :-)

English: This is slides and video from the Norwegian lightning presentation on character encoding I did at the JavaZone 2011 conference today.

Takk for nok en knall konferanse :-)

Her er slidene mine fra lyntalen om tegnsettenkoding jeg holdt på JavaZone 2011 i dag. PDF-versjon er også tilgjengelig, by popular demand.

Og her er videoen ute, mindre enn åtte timer senere. Smidig! :-)

pyspotify is a Python wrapper for libspotify, which give developers access to the Spotify music streaming service.

Today, I tagged pyspotify 1.2 at GitHub and pushed the new release to PyPI. I’ve also made deb packages of libspotify and pyspotify available at apt.mopidy.com.

The 1.2 release brings pyspotify up to date with libspotify 0.0.8, which was released by Spotify a couple of weeks ago. It also fixes a bunch of memory issues. pyspotify does not implement the full libspotify API, but a significant and usable part of it. With pyspotify 1.2 all the old and broken unit tests have been fixed, and a bunch of new tests have been developed. For the first time, pyspotify is documented, and it comes with a new web site.

This is the first release of pyspotify to PyPI since Doug Winter’s release of 1.1 in April 2010. Since Doug hasn’t found the time to maintain pyspotify further, Johannes Knutsen and myself have been patching pyspotify somewhat ad hoc, adding just what we needed to keep pyspotify barely working with the new releases of libspotify and Mopidy. Back in January, I explored the use of Cython for a new alternative libspotify binding, spoticy. Using Cython for this was a great success as far as I took it, but I had other Mopidy related side projects to complete first (aka Pykka). Because Mopidy depends heavily on pyspotify, I also asked Doug to transfer the maintenance of pyspotify to the Mopidy project, which he finally decided to do now in May.

In February, Antoine Pierlot-Garcin started sending us patches for our branch of pyspotify. Since then, he has been steadily improving pyspotify. All the improvements listed above is due to Antoine’s work, and the 1.2 release is to his credit.

I hope this will make the situation around pyspotify clearer, and that we’ll soon see more projects using pyspotify to do great stuff with the Spotify service.

Le pyspotify est mort, vive le pyspotify.

The following is a cleaned up log I wrote for myself while debugging a bug. Writing a log while working helps me keep track of the debugging effort in case I’m interrupted (life, sleep, work, etc.). It also requires me to explain all findings to myself in fully spelled out sentences, making my thoughts considerably easier to follow.

In addition to serving as an example of a personal debug log, I hope it can be useful as an introduction to debugging segfaults or other low-level bugs.

How to reproduce

I have three computers running Ubuntu 11.04. Mopidy revision 9c23949 consistently crashes with a segfault on one of them when I do the following:

1. Start Mopidy.
2. Connect with an MPD client, e.g. ncmpcpp.
3. Search for anything, e.g. foo.
4. Wait less than 10 seconds for the segfault to happen. It always happens directly after a log message from Mopidy’s Spotify backend stating that it is Updating metadata.

Rule out the obvious

I check that I’m actually using the latest versions of the important pieces of software, not just some old version I installed by hand and forgot about.

I try uninstalling pyspotify v1.1+mopidy20110405 installed from my own Debian package, and install the latest revision (c6e2a02) from Git instead. Still the same error.

Nobody has reported the same problem, even though both other developers and users should have been on the same mix of versions for the last couple of months.

Digging in

Luckily I can consistently reproduce the segfault in less than 20 seconds of work. I’m not too familiar with debugging C programs and especially the infamous segfaults, but I’m taking on this fight.

I expect the problem to be in pyspotify, as the rest of the code is either pure Python or more well-tested and broadly used libraries. Also the segfault consistently happens directly after a log message from Mopidy’s Spotify backend.

Antoine Pierlot-Garcin, the new main contributor to pyspotify, says to rebuild pyspotify with CFLAGS="-g -O0". -g will include debug information that gdb will understand in the resulting binary. -O0 will override the -O2 default of the pyspotify build system, and turn off any optimizations to ease the debugging.

Googling “debugging segfaults” yields a nice howto on debugging segfaults.

In summary: Get a core dump, inspect it with gdb.

Possible causes: “There are four common mistakes that lead to segmentation faults: dereferencing NULL, dereferencing an uninitialized pointer, dereferencing a pointer that has been freed (or deleted, in C++) or that has gone out of scope (in the case of arrays declared in functions), and writing off the end of an array.”

Rerunning Mopidy nothing more interesting happens, except the usual segfault. No core dump is produced.

Hum, how to get a core dump? I’ve done it before, but I can’t remember. Google helps.

I try ulimit -c 50000 to get a core dump of maximum 50MB, and then reproduce the segfault.

Run python mopidy -v, connect with ncmpcpp, search for foo, wait less than 10 seconds. Kaboom:

DEBUG    2011-05-23 20:07:02,030 [7659:SpotifySMThread] mopidy.backends.spotify.session_manager
  Metadata updated
  Segmentation fault (core dumped)

Loads the core dump up in gdb:

gdb /usr/bin/python core

gdb complains that the core dump is truncated, and that is should be approximately 180MB.

man bash and search for ulimit. Aha. I can specify unlimited. But I’m not allowed to? Restart shell, run ulimit -c unlimited again. Works.

Rerun Mopidy to get an untruncated core dump.

Analyzing the core dump

Yay! gdb loads debug symbols from all the linked libraries that got them available. Notably, the proprietary libspotify library does not include debug symbols. So what does gdb say?

Core was generated by `python mopidy -v'.
Program terminated with signal 11, Segmentation fault.
#0  0x00007fef50dae5f0 in sp_album_add_ref () from /usr/lib/libspotify.so.7
(gdb)

Verifying a hypothesis

According to the libspotify docs for the album subsystem sp_album_add_ref takes an sp_album struct and increases the reference count of the album. Looking back at the list of reasons for segfaults from the segfault debugging howto, it may sound as we increase the reference count of NULL, which obviously isn’t good. Let’s see if that hypothesis is correct…

Looking in the howto for ways to proceed, backtrace reveals the events happening just before the segfault:

(gdb) backtrace
#0  0x00007fef50dae5f0 in sp_album_add_ref () from /usr/lib/libspotify.so.7
#1  0x00007fef51048801 in Track_album (self=0x7fef4d155a50) at src/track.c:72
#2  0x00000000004970ef in call_function (f=<value optimized out>, throwflag=<value optimized out>) at ../Python/ceval.c:3997
#3  PyEval_EvalFrameEx (f=<value optimized out>, throwflag=<value optimized out>) at ../Python/ceval.c:2666

Moving one step up the stack, we get to the pyspotify code:

(gdb) up
#1  0x00007fef51048801 in Track_album (self=0x7fef4d155a50) at src/track.c:72
72	    sp_album_add_ref(album);

Our guess was that we’re increasing the reference count on an album that is null. Let’s see what album actually was…

(gdb) print album
$1 = (sp_album *) 0x0

A pointer to an sp_album struct at the address 0x0, also known as NULL. Hypothesis confirmed.

Finding a solution

Let’s take a look at the pyspotify code in question:

static PyObject *Track_album(Track *self) {
    sp_album *album;

    album = sp_track_album(self->_track);
    Album *a = (Album *)PyObject_CallObject((PyObject *)&AlbumType, NULL);
    sp_album_add_ref(album);
    a->_album = album;
    return (PyObject *)a;
}

We create a pointer to a sp_album struct. Given a Spotify track, we request a reference to the related album, and assign the result to our pointer. Then we create an Album Python object, before we increase the reference count on the sp_album and give the reference to the Python object. Finally, the Python object is returned.

Lets try just returning NULL if we get NULL from sp_track_album:

diff --git a/src/track.c b/src/track.c
index f0d5956..3284029 100644
--- a/src/track.c
+++ b/src/track.c
@@ -68,6 +68,9 @@ static PyObject *Track_album(Track *self) {
     sp_album *album;
 
     album = sp_track_album(self->_track);
+    if (album == NULL) {
+        return NULL;
+    }
     Album *a = (Album *)PyObject_CallObject((PyObject *)&AlbumType, NULL);
     sp_album_add_ref(album);
     a->_album = album;

If we rebuild pyspotify and try to reproducing the segfault, we now get a familiar Python traceback instead:

/usr/lib/python2.7/threading.py:828: RuntimeWarning: tp_compare didn't return -1 or -2 for exception
  return _active[_get_ident()]
ERROR    2011-05-23 22:33:05,214 [10571:SpotifySMThread] mopidy.utils.process
  error return without exception set
Traceback (most recent call last):
  File "/home/jodal/dev/mopidy/mopidy/utils/process.py", line 21, in run
    self.run_inside_try()
  File "/home/jodal/dev/mopidy/mopidy/backends/spotify/session_manager.py", line 40, in run_inside_try
    self.connect()
  File "/usr/local/lib/python2.7/dist-packages/pyspotify-1.1-py2.7-linux-x86_64.egg/spotify/manager.py", line 48, in connect
    self.loop(sess) # returns on disconnect
  File "/usr/local/lib/python2.7/dist-packages/pyspotify-1.1-py2.7-linux-x86_64.egg/spotify/manager.py", line 58, in loop
    self.timer = threading.Timer(timeout/1000.0, self.awoken.set)
  File "/usr/lib/python2.7/threading.py", line 731, in Timer
    return _Timer(*args, **kwargs)
  File "/usr/lib/python2.7/threading.py", line 742, in __init__
    Thread.__init__(self)
  File "/usr/lib/python2.7/threading.py", line 446, in __init__
    self.__daemonic = self._set_daemon()
  File "/usr/lib/python2.7/threading.py", line 470, in _set_daemon
    return current_thread().daemon
  File "/usr/lib/python2.7/threading.py", line 828, in currentThread
    return _active[_get_ident()]
  File "/home/jodal/dev/mopidy/mopidy/backends/spotify/session_manager.py", line 73, in metadata_updated
    self.refresh_stored_playlists()
  File "/home/jodal/dev/mopidy/mopidy/backends/spotify/session_manager.py", line 131, in refresh_stored_playlists
    SpotifyTranslator.to_mopidy_playlist(spotify_playlist))
  File "/home/jodal/dev/mopidy/mopidy/backends/spotify/translator.py", line 62, in to_mopidy_playlist
    if str(Link.from_track(t, 0))],
  File "/home/jodal/dev/mopidy/mopidy/backends/spotify/translator.py", line 34, in to_mopidy_track
    if dt.MINYEAR <= int(spotify_track.album().year()) <= dt.MAXYEAR:
SystemError: error return without exception set

Note that we get a SystemError and not e.g. AttributeError: 'NoneType' object has no attribute 'year' which we would expect if album() returned None. This is because we return NULL from Track_album, which Python considers an “error return”, without setting an exception code first. If we want to return None on failure instead of throwing an exception, we can change track.c as follows:

diff --git a/src/track.c b/src/track.c
index f0d5956..82897de 100644
--- a/src/track.c
+++ b/src/track.c
@@ -68,6 +68,8 @@ static PyObject *Track_album(Track *self) {
     sp_album *album;
 
     album = sp_track_album(self->_track);
+    if (!album)
+        Py_RETURN_NONE;
     Album *a = (Album *)PyObject_CallObject((PyObject *)&AlbumType, NULL);
     sp_album_add_ref(album);
     a->_album = album;

Rebuilding pyspotify again, and reproducing the error, we now get the expected Python error which we can handle nicely:

File "/home/jodal/dev/mopidy/mopidy/backends/spotify/session_manager.py", line 73, in metadata_updated
    self.refresh_stored_playlists()
  File "/home/jodal/dev/mopidy/mopidy/backends/spotify/session_manager.py", line 131, in refresh_stored_playlists
    SpotifyTranslator.to_mopidy_playlist(spotify_playlist))
  File "/home/jodal/dev/mopidy/mopidy/backends/spotify/translator.py", line 62, in to_mopidy_playlist
    if str(Link.from_track(t, 0))],
  File "/home/jodal/dev/mopidy/mopidy/backends/spotify/translator.py", line 34, in to_mopidy_track
    if dt.MINYEAR <= int(spotify_track.album().year()) <= dt.MAXYEAR:
AttributeError: 'NoneType' object has no attribute 'year'

By this point, I consider the bug squashed and ready to be reported.

The only part left is to decide how to best fix it. E.g. if album() should return None, throw an exception, or maybe return an empty album object. That’s another story.