Amazingly, one of the most popular links on this site is the quick tip, Getting free diskspace in python.

One of the comments shows that this method doesn’t work on Windows. Here’s a version that does:

import win32file
def freespace(p):
    """
    Returns the number of free bytes on the drive that ``p`` is on
    """
    secsPerClus, bytesPerSec, nFreeClus, totClus = win32file.GetDiskFreeSpace(p)
    return secsPerClus * bytesPerSec * nFreeClus

The win32file module is part of the pywin32 extension module.

I’ve just pushed poster 0.6.0 to the cheeseshop.

Thanks again to everybody who sent in bug reports, and for letting me know how you’re using poster! It’s really great to hear from users.

poster 0.6.0 fixes a few problems with 0.5, most notably:

• Documentation updates to clarify some common use cases.
• Added a poster.version attribute. Thanks to JP!
• Fix for unicode filenames. Thanks to Zed Shaw.
• Handle StringIO file objects. Thanks to Christophe Combelles.

poster 0.6.0 can be downloaded from the cheeseshop, or from my website. Documentation can be found at http://atlee.ca/software/poster/

Mozilla has been quite involved in recent buildbot development, in particular, helping to make it scale across multiple machines. More on this in another post!

Once deployed, these changes will give us the ability to give real time access to various information about our build queue: the list of jobs waiting to start, and which jobs are in progress. This should help other tools like Tinderboxpushlog show more accurate information. One limitation of the upstream work so far is that it only captures a very coarse level of detail about builds: start/end time, and result code is pretty much it. No further detail about the build is captured, like which slave it executed on, what properties it generated (which could include useful information like the URL to the generated binaries), etc.

We’ve also been exporting a json dump of our build status for many months now. It’s been useful for some analysis, but it also has limitations: the data is always at least 5 minutes old by the time you look, and in-progress builds are not represented at all.

We’re starting to look at ways of exporting all this detail in a way that’s useful to more people. You want to get notified when your try builds are done? You want to look at which test suites are taking the most time? You want to determine how our build times change over time? You want to find out what the last all-green revision was on trunk? We want to make this data available, so anybody can write these tools.

Just how big is that firehose?

I think we have one of the largest buildbot setups out there and we generate a non-trivial amount of data:

• 6-10 buildbot master processes generating updates, on different machines in 2 or 3 data centers
• around 130 jobs per hour composed of 4,773 individual steps total per hour. That works out to about 1.4 updates per second that are generated

How you can help

This is where you come in.

I can think of two main classes of interfaces we could set up: a query-type interface where you poll for information that you are interested in, and a notification system where you register a listener for certain types (or all!) events.

What would be the best way for us to make this data available to you? Some kind of REST API? A message or event brokering system? pubsubhubbub?

Is there some type of data or filtering that would be super helpful to you?

It seems like it was ages ago when I posted about profiling buildbot.

One of the hot spots identified there was the dataReceived call. This has been sped up a little bit in recent versions of twisted, but our buildbot masters were still severely overloaded.

It turns out that the buildbot slaves make a lot of RPC calls when sending log data, which results in tens of thousands of dataReceived calls. Multiply that by several dozen build slaves sending log data peaking at a combined throughput of 10 megabits/s and you’ve got an awful lot of data to handle.

By adding a small slave-side buffer, the number of RPC calls to send log data is drastically reduced by an order of magnitude in some tests, resulting in a much better load situation on the master. This is good for us, because it means the masters are much more responsive, and it’s good for everybody else because it means we have fewer failures and wasted time due to the master being too busy to handle everything. It also means we can throw more build slaves onto the masters!

The new code was deployed towards the end of the day on the 26th, or the end of the 12th week.

I’ve just released version 0.5 of poster, the streaming http upload library for python. It’s easy_installable or downloadable directly from the cheeseshop.

Thanks again to everybody who’s written in with bug fixes and suggestions!

Buildbot is a critical part of our build infrastructure at Mozilla. We use it to manage builds on 5 different platforms (Linux, Mac, Windows, Maemo and Windows Mobile), and 5 different branches (mozilla-1.9.1, mozilla-central, TraceMonkey, Electrolysis, and Places). All in all we have 80 machines doing builds across 150 different build types (not counting Talos; all the Talos test runs and slaves are managed by a different master).

And buildbot is at the center of it all.

The load on our machine running buildbot is normally fairly high, and occasionally spikes so that the buildbot process is unresponsive. It normally restores itself within a few minutes, but I’d really like to know why it’s doing this!

Running our staging buildbot master with python’s cProfile module for almost two hours yields the following profile:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   416377 4771.188    0.011 4796.749    0.012 {select.select}
       52  526.891   10.133  651.043   12.520 /tools/buildbot/lib/python2.5/site-packages/buildbot-0.7.10p1-py2.5.egg/buildbot/status/web/waterfall.py:834(phase2)
     6518  355.370    0.055  355.370    0.055 {posix.fsync}
   232582  238.943    0.001 1112.039    0.005 /tools/twisted-8.0.1/lib/python2.5/site-packages/twisted/spread/banana.py:150(dataReceived)
 10089681  104.395    0.000  130.089    0.000 /tools/twisted-8.0.1/lib/python2.5/site-packages/twisted/spread/banana.py:36(b1282int)
36798140/36797962   83.536    0.000   83.537    0.000 {len}
 29913653   70.458    0.000   70.458    0.000 {method 'append' of 'list' objects}
      311   63.775    0.205   63.775    0.205 {bz2.compress}
 10088987   56.581    0.000  665.982    0.000 /tools/twisted-8.0.1/lib/python2.5/site-packages/twisted/spread/banana.py:141(gotItem)
4010792/1014652   56.079    0.000  176.693    0.000 /tools/twisted-8.0.1/lib/python2.5/site-packages/twisted/spread/jelly.py:639(unjelly)
2343910/512709   47.954    0.000  112.446    0.000 /tools/twisted-8.0.1/lib/python2.5/site-packages/twisted/spread/banana.py:281(_encode)

Interpreting the results

select shows up in the profile because we’re profiling wall clock time, not cpu time. So the more time we’re spending in select, the better, since that means we’re just waiting for data. The overall run time for this profile was 7,532 seconds, so select is taking around 63% of our total time. I believe the more time spent here, the better. Time spent inside select is idle time.

We already knew that the buildbot waterfall was slow (the second line in profile).

fsync isn’t too surprising either. buildbot calls fsync after writing log files to disk. We’ve considered removing this call, and this profile lends support to our original guess.

The next entries really surprised me, twisted’s dataReceived and a decoding function, b1282int. These are called when processing data received from the slaves. If I’m reading this correctly, this means that dataReceived and children account for around 40% of our total time after you remove the time spent in select. 1112 / (7532-4796) = 40%.

These results are from our staging buildbot master, which doesn’t have anywhere near the same load as the production buildbot master. I would expect that the time spent waiting in select would go down on the production master (there’s more data being received, more often), and that time spent in fsync and dataReceived would go up.

What to do about it?

A few ideas….

• Use psyco to get some JIT goodness applied to some of the slower python functions.
• Remove the fsync call after saving logs.
• Use the cpu-time to profile rather than wallclock time. This will give a different perspective on the performance of buildbot, which should give better information about where we’re spending time processing data.
• Implement slow pieces in C (or cython). Twisted’s Banana library looks do-able in C, and also is high up in the profile.
• Send less data from the slaves. We’re currently logging all stdout/stderr produced by the slaves. All of this data is processed by the master process and then saved to disk.
• Rearchitect buildbot to handle this kind of load.
• Have more than one buildbot master, each one handling fewer slaves. We’re actively looking into this approach, since it also allows us to have some redundancy for this critical piece of our infrastructure.

I’m happy to announce the release of poster version 0.4.

This is a bug fix release, which fixes problems when trying to use poster over a secure connection (with https).

I’ve also reworked some of the code so that it can hopefully work with python 2.4. It passes all the unit tests that I have under python 2.4 now, but since I don’t normally use python 2.4, I’d be interested to hear other people’s experience using it.

One of the things that I love about working on poster, and about open source software in general, is hearing from users all over the world who have found it helpful in some way. It’s always encouraging to hear about how poster is being used, so thank you to all who have e-mailed me!

poster can be downloaded from my website, or from the cheeseshop.

As always, bug reports, comments, and questions are always welcome.

I’ve been trying to use Mercurial Queues to manage my work on different tasks in several repositories. I try to name all my patches with the name of the bug it’s related to; so for my recent work on getting Talos not skipping builds, I would call my patch ‘bug468731′.

I noticed that I was running this series of steps a lot:
cd ~/mozilla/buildbot-configs
hg qdiff > ~/patches/bug468731-buildbot-configs.patch
cd ~/mozilla/buildbotcustom
hg qdiff > ~/patches/bug468731-buildbotcustom.patch

…and then uploading the resulting patch files as attachments to the bug. There’s a lot of repetition and extra mental work in those steps:

• I have to type the bug number manually twice. This is annoying, and error-prone. I’ve made a typo on more than one occasion and then wasted a few minutes trying to track down where the file went.
• I have to type the correct repository name for each patch. Again, I’ve managed to screw this up in the past. Often I have several terminals open, one for each repository, and I can get mixed up as to which repository I’ve currently got active.
• mercurial already knows the bug number, since I’ve used it in the name of my patch.
• mercurial already knows which repository I’m in.

I wrote the mercurial extension below to help with this. It will take the current patch name, and the basename of the current repository, and save a patch in ~/patches called [patch_name]-[repo_name].patch. It will also compare the current patch to any previous ones in the patches directory, and save a new file if the patches are different, or tell you that you’ve already saved this patch.

To enable this extension, save the code below somewhere like ~/.hgext/mkpatch.py, and then add “mkpatch = ~/.hgext/mkpatch.py” to your .hgrc’s extensions section. Then you can run ‘hg mkpatch’ to automatically create a patch for you in your ~/patches directory!

import os, hashlib
 
from mercurial import commands, util
from hgext import mq
 
def mkpatch(ui, repo, *pats, **opts):
    """Saves the current patch to a file called <patch_name>-<repo_name>.patch
    in your patch directory (defaults to ~/patches)
    """
    repo_name = os.path.basename(ui.config('paths', 'default'))
    if opts.get('patchdir'):
        patch_dir = opts.get('patchdir')
        del opts['patchdir']
    else:
        patch_dir = os.path.expanduser(ui.config('mkpatch', 'patchdir', "~/patches"))
 
    ui.pushbuffer()
    mq.top(ui, repo)
    patch_name = ui.popbuffer().strip()
 
    if not os.path.exists(patch_dir):
        os.makedirs(patch_dir)
    elif not os.path.isdir(patch_dir):
        raise util.Abort("%s is not a directory" % patch_dir)
 
    ui.pushbuffer()
    mq.diff(ui, repo, *pats, **opts)
    patch_data = ui.popbuffer()
    patch_hash = hashlib.new('sha1', patch_data).digest()
 
    full_name = os.path.join(patch_dir, "%s-%s.patch" % (patch_name, repo_name))
    i = 0
    while os.path.exists(full_name):
        file_hash = hashlib.new('sha1', open(full_name).read()).digest()
        if file_hash == patch_hash:
            ui.status("Patch is identical to ", full_name, "; not saving")
            return
        full_name = os.path.join(patch_dir, "%s-%s.patch.%i" % (patch_name, repo_name, i))
        i += 1
 
    open(full_name, "w").write(patch_data)
    ui.status("Patch saved to ", full_name)
 
mkpatch_options = [
        ("", "patchdir", '', "patch directory"),
        ]
cmdtable = {
    "mkpatch": (mkpatch, mkpatch_options + mq.cmdtable['^qdiff'][1], "hg mkpatch [OPTION]... [FILE]...")
}

I’ve fixed a few bugs with poster, and released the next version, 0.2. It’s available from the cheeseshop, or from my web page.

Documentation can also be found here.

At Mozilla, we use buildbot to coordinate performing builds, unit tests, performance tests, and l10n repacks across all of our build slaves.

There is a lot of activity on a project the size of Firefox, which means that the build slaves are kept pretty busy most of the time.

Unfortunately, like most software out there, our buildbot code has bugs in it. buildbot provides two ways of picking up new changes to code and configuration: ‘buildbot restart’ and ‘buildbot reconfig’.

Restarting buildbot is the cleanest thing to do: it shuts down the existing buildbot process, and starts a new one once the original has shut down cleanly. The problem with restarting is that it interrupts any builds that are currently active.

The second option, ‘reconfig’, is usually a great way to pick up changes to buildbot code without interrupting existing builds. ‘reconfig’ is implemented by sending SIGHUP to the buildbot process, which triggers a python reload() of certain files.

This is where the problem starts.

Reloading a module basically re-initializes the module, including redefining any classes that are in the module…which is what you want, right? The whole reason you’re reloading is to pick up changes to the code you have in the module!

So let’s say you have a module, foo.py, with these classes:

class Foo(object):
    def foo(self):
        print "Foo.foo"
 
class Bar(Foo):
    def foo(self):
        print "Bar.foo"
        Foo.foo(self)

and you’re using it like this:

>>> import foo
>>> b = foo.Bar()
>>> b.foo()
Bar.foo
Foo.foo

Looks good! Now, let’s do a reload, which is what buildbot does on a ‘reconfig’:

>>> reload(foo)
<module 'foo' from 'foo.pyc'>
>>> b.foo()
Bar.foo
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/Users/catlee/test/foo.py", line 13, in foo
    Foo.foo(self)
TypeError: unbound method foo() must be called with Foo instance as first argument (got Bar instance instead)

Whoops! What happened? The TypeError exception is complaining that Foo.foo must be called with an instance of Foo as the first argument. (NB: we’re calling the unbound method on the class here, not a bound method on the instance, which is why we need to pass in ‘self’ as the first argument. This is typical when calling your parent class)

But wait! Isn’t Bar a sub-class of Foo? And why did this work before? Let’s try this again, but let’s watch what happens to Foo and Bar this time, using the id() function:

>>> import foo
>>> b = foo.Bar()
>>> id(foo.Bar)
3217664
>>> reload(foo)
<module 'foo' from 'foo.pyc'>
>>> id(foo.Bar)
3218592

(The id() function returns a unique identifier for objects in python; if two objects have the same id, then they refer to the same object)

The id’s are different, which means that we get a new Bar class after we reload…I guess that makes sense. Take a look at our b object, which was created before the reload:

>>> b.__class__
<class 'foo.Bar'>
>>> id(b.__class__)
3217664

So b is an instance of the old Bar class, not the new one. Let’s look deeper:

>>> b.__class__.__bases__
(<class 'foo.Foo'>,)
>>> id(b.__class__.__bases__[0])
3216336
>>> id(foo.Foo)
3218128

A ha! The old Bar’s base class (Foo) is different than what’s currently defined in the module. After we reloaded the foo module, the Foo class was redefined, which is presumably what we want. The unfortunate side effect of this is that any references by name to the class ‘Foo’ will pick up the new Foo class, including code in methods of subclasses. There are probably other places where this has unexpected results, but for us, this is the biggest problem.

Reloading essentially breaks class inheritance for objects whose lifetime spans the reload. Using super() in the normal way doesn’t even work, since you usually refer to your instance’s class by name:

class Bar(Foo):
    def foo(self):
        print "Bar.foo"
        super(Bar, self).foo()

If you’re using new-style classes, it looks like you can get around this by looking at your __class__ attribute:

class Bar(Foo):
    def foo(self):
        print "Bar.foo"
        super(self.__class__, self).foo()

Buildbot isn’t using new-style classes…yet…so we can’t use super(). Another workaround I’m playing around with is to use the inspect module to get at the class hierarchy:

def get_parent(obj, n=1):
    import inspect
    return inspect.getmro(obj.__class__)[n]
 
class Bar(Foo):
    def foo(self):
        print "Bar.foo"
        get_parent(self).foo(self)