Showing posts with label python. Show all posts
Showing posts with label python. Show all posts

Wednesday, August 4, 2010

Step-by-step Meliae

Some people asked me to provide a step-by-step guide to how to debug memory using Meliae. I just ran into another unknown situation, so I figured I'd post a step-by-step along with rationale for why I'm doing it.
  1. First is loading up the data. This was a dump while running 'bzr pack' of a large repository.
    >>> from meliae import loader
    >>> om = loader.load('big.dump')
    >>> om.remove_expensive_references()
    The last step is done because otherwise instances keep a reference to their class, and classes reference their base types, and you end up getting to 'object', and somewhere along the way you end up referencing too much. I don't do it automatically, because it does remove actual references, which someone might want to keep.
  2. Then, do a big summary, just to get started
    >>> om.summarize()
    Total 8364538 objects, 286 types, Total size = 440.4MiB (461765737 bytes)
    Index Count % Size % Cum Max Kind
    0 2193778 26 181553569 39 39 4194281 str
    1 12519 0 97231956 21 6012583052 dict
    2 1599439 19 68293428 14 75 304 tuple
    3 3459765 41 62169616 13 88 20 bzrlib._static_tuple_c.StaticTuple
    4 82 0 29372712 6 94 8388724 set
    5 1052573 12 12630876 2 97 12 int
    6 1644 0 4693700 1 98 2351848 list
    7 4038 0 2245128 0 99 556 _LazyGroupCompressFactory
  3. You can see that
    1. There are 8M objects, and about 440MB of reachable memory.
    2. The vast bulk of that is in strings, but there are also some oddities, like that 12.5MB dictionary
  4. At this point, I wanted to understand what was up with that big dictionary.
    >>> dicts = om.get_all('dict')
    >>> dicts[0]
    dict(417338688 12583052B 1045240refs 2par)
    om.get_all() gives you a list of all objects matching the given type string. It also sorts the returned list, so that the biggest items are at the
    beginning.
  5. Now lets look around a bit, to try to figure out where this dict lives
    >>> bigd = dicts[0]
    >>> from pprint import pprint as pp
    We'll use pprint a lot, so map it to something easy to type.
    >>> pp(bigd.p)
    [frame(39600120 464B 23refs 1par '_get_remaining_record_stream'),
    _BatchingBlockFetcher(180042960 556B 17refs 3par)]
  6. So this dict is contained in a frame, but also an attribute of _BatchingBlockFetcher. Let's try to see which attribute it is.
    >>> pp(bigd.p[1].refs_as_dict())
    {'batch_memos': dict(584888016 140B 4refs 1par),
    'gcvf': GroupCompressVersionedFiles(571002736 556B 13refs 9par),
    'keys': list(186984208 16968B 4038refs 2par),
    'last_read_memo': tuple(536280880 40B 3refs 1par),
    'locations': dict(417338688 12583052B 1045240refs 2par),
    'manager': _LazyGroupContentManager(584077552 172B 7refs 3716par),
    'memos_to_get': list(186983248 52B 1refs 2par),
    'total_bytes': 774119}
  7. It takes a bit to look through that, but you can see:
    'locations': dict(417338688 12583052B 1045240refs 2par)
    Note that 1045240refs means there are 522k key:value pairs in this dict.
  8. How much total memory is this dict referencing?
    >>> om.summarize(bigd)
    Total 4035636 objects, 22 types, Total size = 136.8MiB (143461221 bytes)
    Index Count % Size % Cum Max Kind
    0 1567864 38 66895512 46 46 52 tuple
    1 285704 7 24972909 17 64 226 str
    2 1142424 28 20757800 14 78 20 bzrlib._static_tuple_c.StaticTuple
    ...
    8 2 0 1832 0 99 1684 FIFOCache
    9 35 0 1120 0 99 32 _InternalNode
  9. So about 136MB out of 440MB is reachable from this dict. However, I'm noticing that FIFOCache and _InternalNode is also reachable, and those don't really seem to fit. I also notice that there are 1.6M tuples here, which is often a no-no. (If we are going to have that many tuples, we probably want them to be StaticTuple() because they use a fair amount less memory, can be interned, and aren't in the garbage collector. So lets poke around a little bit
    >>> bigd[0]
    bzrlib._static_tuple_c.StaticTuple(408433296 20B 2refs 9par)
    >>> bigd[1]
    tuple(618390272 44B 4refs 1par)
    >>> pp(bigd[0].c)
    [str(40127328 80B 473par 'svn-v4:138bc75d-0d04-0410-961f-82ee72b054a4:trunk:126948'),
    str(247098672 85B 37par '14@138bc75d-0d04-0410-961f-82ee72b054a4:trunk%2Fgcc%2Finput.h')]
    >>> pp(bigd[1].c)
    [tuple(618383880 36B 2refs 1par),
    bzrlib._static_tuple_c.StaticTuple(569848240 16B 1refs 3par),
    NoneType(505223636 8B 1074389par),
    tuple(618390416 48B 5refs 1par)]
    One thing to note, dict references are [key1, value1, key2, value2] while tuple references are (last, middle, first). I don't know why tuple.tp_traverse traverses in reverse order, but it does. And StaticTuple followed its lead.
    The things to take away from this is
    1. It is mapping a StaticTuple(file_id, revision_id) => tuple()
    2. The target tuple is actually quite complex, so we'll have to dig a bit deeper to figure it out.
    3. The file-id and revision-id are both referenced many times (37 and 473 respectively), so we seem to be doing a decent job sharing those strings.
  10. At this point, I would probably pull up the source code for _BatchingBlockFetcher, to try and figure out what is so big for locations. Looking at the source code, it is actually built in _get_remaining_record_stream as:
    locations = self._index.get_build_details(keys)
    This is then defined as returning:
      :return: A dict of key: (index_memo, compression_parent, parents, record_details).
  11. And the index memo contains a reference to the indexes themselves, but they don't really 'own' them. So lets filter them out:
    >>> indexes = om.get_all('BTreeGraphIndex')
    >>> om.summarize(bigd, excluding=[o.address for o in indexes])
    Total 3740667 objects, 6 types, Total size = 122.9MiB (128855911 bytes)
    Index Count % Size % Cum Max Kind
    0 1567860 41 66895360 51 51 48 tuple
    1 189162 5 19690647 15 67 226 str
    2 948160 25 17261048 13 80 20 bzrlib._static_tuple_c.StaticTuple
    3 1 0 12583052 9 9012583052 dict
    4 1035483 27 12425796 9 99 12 int
    5 1 0 8 0 100 8 NoneType
    (It is currently a bit clumsy that you have to do [o.address], but it means you can use large sets of ints. I'm still trying to sort that out.)
    The memory consumption here looks more realistic. You can also see that just the tuple objects by themselves consume 67MB, or 51% of the memory. You can also see that for a dict holding 500k entries, we have 1.5M tuples. So we are using 3 tuples per key.
  12. Note that we can't just use StaticTuple here, because index_memo[0] is the BTreeGraphIndex. Digging into the code, I think the data is all here:
     result[key] = (self._node_to_position(entry),
    None, parents, (method, None))
    You can see that there is a whole lot of 'None' in this, and we also have an extra tuple at the end which is a bit of a waste (vs just inlining the content). We could save 28 bytes/record (or 28*500k = 14MB) by just inlining that last (method, None). Though it changes some apis.
  13. Another thing to notice is that if you grep through the source code for uses of 'locations', you can see that we use the parents info and the index_memo, but we just ignore everything else. (method, compression_parent, and eol info are never interesting here). So really the result could be:
    result[key] = (self._node_to_position(entry), parents)
    This would be 28 + 4*2 = 36 vs (28+4*4 + 28+4*2) = 80, or saving 44b/record*.5M = 22MB. That is about 20% of that 122MB. Which isn't huge, but isn't a lot of effort to get. We could get a little better if we could collapse the node_to_position info along side the parents info, etc. (Say with a custom object.) That could shave another 28 bytes for the tuple, and maybe one extra reference.
  14. I ended up working on this, because it was like a 10 minute thing. I ended up creating this class (code at lp:
    class _GCBuildDetails(object):
    """A blob of data about the build details.

    This stores the minimal data, which then allows compatibility with the old
    api, without taking as much memory.
    """

    __slots__ = ('_index', '_group_start', '_group_end', '_basis_end',
    '_delta_end', '_parents')

    method = 'group'
    compression_parent = None

    def __init__(self, parents, position_info):
    self._parents = parents
    self._index = position_info[0]
    self._group_start = position_info[1]
    # Is this _end or length? Doesn't really matter to us
    self._group_end = position_info[2]
    self._basis_end = position_info[3]
    self._delta_end = position_info[4]

    def __repr__(self):
    return '%s(%s, %s)' % (self.__class__.__name__,
    self.index_memo, self._parents)

    @property
    def index_memo(self):
    return (self._index, self._group_start, self._group_end,
    self._basis_end, self._delta_end)

    @property
    def record_details(self):
    return static_tuple.StaticTuple(self.method, None)

    def __getitem__(self, offset):
    """Compatibility thunk to act like a tuple."""
    if offset == 0:
    return self.index_memo
    elif offset == 1:
    return self.compression_parent # Always None
    elif offset == 2:
    return self._parents
    elif offset == 3:
    return self.record_details
    else:
    raise IndexError('offset out of range')

    def __len__(self):
    return 4
  15. The size of this class is 48 bytes, including the python object and gc overhead. This replaces the tuple(index_memo_tuple(index, start, end, start, end), None, parents, tuple(method, None)). Which is 28+4*4 + 28+4*5 + 28+4*2 = 128 bytes. So we save 80 bytes per record. on my bzr.dev repository that is ~10.6MB, on this dump it would be 40MB.
  16. The other bit to look at is measuring real-world results. Which looks
    something like this:
    >>> from bzrlib import branch, trace, initialize; initialize().__enter__()

    >>> b = branch.Branch.open('.')
    >>> b.lock_read()
    LogicalLockResult(/2.3-gc-build-details/)>)
    >>> keys = b.repository.texts.keys()
    >>> trace.debug_memory('holding all keys')
    WorkingSize 33192KiB PeakWorking 34772KiB holding all keys
    >>> locations = b.repository.texts._index.get_build_details(keys)
    >>> trace.debug_memory('holding all keys')
    WorkingSize 77604KiB PeakWorking 87960KiB holding all keys
    >>>
Hopefully this has been informative. Digging into a bit of memory consumption, and how to determine where memory is being consumed, and a bit of understanding about how you can rework python objects to save a bit of memory (the biggest thing is to try to use fewer objects overall, since every object is at least 24 bytes, and that is if you are using __slots__. If you aren't then it is a minimum of 172 bytes (32 for the base object + 140 for its __dict__).

Tuesday, July 20, 2010

Meliae 0.2.1

Meliae 0.2.1 is now officially released.

The list of changes isn't great, it is mostly a bugfix release. There are a couple of quality-of-life changes.

For example you used to need to do:
>>> om = loader.load(filename)
>>> om.compute_parents()
>>> om.collapse_instance_dicts()

However, that is now done as part of loader.load(). This also goes along with a small bug fix to scanner.dump_all_objects() that makes sure to avoid dumping the gc.get_objects() list, since that is artifact from scanning, and not actually something you care about in the dump file.

Many thanks to Canonical for bringing me to Prague for the Launchpad Epic, giving me some time to work on stuff that isn't just Bazaar.

Saturday, January 9, 2010

Meliae 0.2.0

And here we are, with a new release of Meliae 0.2.0. This is a fairly major reworking of the internals, though it should be mostly compatible with 0.1.2. (The disk format did not change, most of the apis have deprecated thunks to help you migrate.)

The main difference is how data is stored in memory. Instead of using a Python dict + python objects, I know use a custom data collection. Python's generic objects are great for getting stuff going, but I was able to cut memory consumption in half with a custom object. This means that finally, analyzing a 600MB dump takes less than 600MB of memory (currently takes about ~300MB). Of course that also depends on your data structures (600MB dump that is one 500MB string will take up very little memory for analysis.)

The second biggest feature is hopefully a cleaner interface.
  1. Call references 'parents' or 'children'. Indicating objects which point to me, and objects which I point to, respectively. 'ref_list' and 'referrers' was confusing. Both start with 'ref', so it takes a bit to sort them out.
  2. Add attributes to get direct access to parents and children, rather than having to go back through the ObjManager.
  3. Change the formatting strings to be more compact. No longer show the refs by default, since you can get to the objects anyway.
A third minor improvement is support for collapsing old-style classes (ones that don't inherit from 'object'.)

So how about an example. To start with, you need a way to interrupt your running process and get a dump of memory. I can't really give you much help, but you'll end up wanting:
from meliae import scanner
scanner.dump_all_objects('test-file.dump')

(This is the simplest method. There are others that take less memory while dumping, if overhead is a concern.)

Once you have that dump file, start up another python process and let's analyze it.
$ python
>>> from meliae import loader
>>> om = loader.load('test-file.dump')
loaded line 3579013, 3579014 objs, 377.4 / 377.4 MiB read in 79.6s

I recommend just always running these lines. If you used a different method of dumping, there are other things to do, which is why it isn't automatic (yet).
>>> om.compute_parents(); om.collapse_instance_dicts()
set parents 3579013 / 3579014
checked 3579013 / 3579014 collapsed 383480
set parents 3195533 / 3195534

Now we can look at the data, and get a feel for where our memory has gone:
>>> s  = om.summarize(); s
Total 3195534 objects, 418 types, Total size = 496.8MiB (520926557 bytes)
Index Count % Size % Cum Max Kind
0 189886 5 211153232 40 40 1112 Thread
1 199117 6 72510520 13 5412583192 dict
2 189892 5 65322848 12 66 344 _Condition
3 380809 11 30464720 5 72 80 instancemethod
4 397892 12 28673968 5 78 2080 tuple
5 380694 11 27409968 5 83 72 builtin_function_or_method
6 446606 13 26100905 5 88 14799 str
7 189886 5 21267232 4 92 112 _socketobject
8 197255 6 14568080 2 95 14688 list
...

At this point, you can see that there are 190k instances of Thread, which is consuming 40% of all memory. There is also a very large 12.5MB dict. (It turns out that this dict holds all of those Thread objects.)

But how do we determine that. One thing we can do is just get a handle to all of those Thread instances
>>> threads = om.get_all('Thread')
>>> threads[0]
Thread(32874448 1112B 23refs 3par)

So this thread is at address 32874448 (not particularly relevant), consumes 1112 bytes of memory (including its dict, since we collapsed threads), references 23 python objects, and is referenced by 3 python objects.

Lets see those references
>>> threads[0].c # shortcut for 'children'
[str(11409312 54B 189887par '_Thread__block'), _Condition(32903248 344B 11refs
1par), str(11408976 53B 189887par '_Thread__name'), str(32862080 77B 1par
'PoolThread-twisted.internet.reactor-1'), str(1...

It looks like there might be something interesting there, but it is a bit hard to sort out. Step one is to try using python's pprint utility.
>>> from pprint import pprint as pp
>>> pp(threads[0].c)
[str(11409312 54B 189887par '_Thread__block'),
_Condition(32903248 344B 11refs 1par),
str(11408976 53B 189887par '_Thread__name'),
str(32862080 77B 1par 'PoolThread-twisted.internet.reactor-1'),
str(11429168 57B 189887par '_Thread__daemonic'),
bool(7478912 24B 572370par 'False'),
str(11409200 56B 189887par '_Thread__started'),
bool(7478944 24B 571496par 'True'),
...

That's a bit better, but I also now that instances have a dict, so lets try:
>>> pp(threads[0].refs_as_dict)
{'_Thread__args': tuple(140013759823952 56B 2008par),
'_Thread__block': _Condition(32903248 344B 11refs 1par),
'_Thread__daemonic': False,
'_Thread__initialized': True,
'_Thread__kwargs': dict(32516192 280B 1par),
'_Thread__name': 'PoolThread-twisted.internet.reactor-1',
'_Thread__started': True,
...

(Note to self, find a good way to shorten 'refs_as_dict', too much typing) Now that is starting to look like you can actually understand what is going on.

Another question to ask, who is referencing this object (why is it still active)?
>>> pp(threads[0].p)
[list(33599432 104B 1refs 1par),
list(33649944 104B 1refs 1par),
dict(11279168 1048B 10refs 1par)]

So this thread is in 2 lists and a dict with 10 items. So what about the parents of the parents
>>> pp(threads[0].p[0].p)
[ThreadPool(32888520 1120B 21refs 2par)]

So the first list is held by a ThreadPool. We can quick check info about that object:
>> pp(threads[0].p[0].p[0].refs_as_dict())
{'joined': False,
'max': 10,
'min': 0,
'name': 'twisted.internet.reactor',
'q': Queue(32888592 1120B 15refs 1par),
'started': True,
'threads': list(33599432 104B 1refs 1par),
'waiters': list(33649944 104B 1refs 1par),
'workers': 1,
'working': list(33649656 72B 1par)}

So that seems to be a Twisted thread pool.
What about the other parents?
>>> pp(threads[0].p[1].p)
[ThreadPool(32888520 1120B 21refs 2par)]

Also a list held by a ThreadPool
>>> pp(threads[0].p[2].p)
[dict(11253824 3352B 98refs 70par)]

Hmmm, now we have a dict pointing to 98 objects which is, itself, referenced by 70 objects. This at least seems worth investigating further.
>>> d = threads[0].p[2].p[0]
>>> d
dict(11253824 3352B 98refs 70par)

Yep, that's the one. We can try to dump it as a dict
>>> pp(d.refs_as_dict())
>>> pp(d.refs_as_dict())
{'BoundedSemaphore': 'BoundedSemaphore',
'Condition': 'Condition',
'Event': 'Event',
'Lock': builtin_function_or_method(10872592 72B 1refs 7par),
'RLock': 'RLock',
'Semaphore': 'Semaphore',
'Thread': 'Thread',
...

Now, the formatting here is actually hiding something. Namely that the referred to object is actually a type:
>>> d.c[1]
type(11280288 880B 4refs 2par '_BoundedSemaphore')

From experience, I know that this is probably a module's dict. It has a lot of objects, and a lot of objects referencing it. (all functions references their modules global dict.) I'm still working on how to collapse a modules __dict__ into the module itself for clarity. Anyway, lets look at the parents to see what module this is.
>>> pp([p for p in d.p if p.type_str == 'module'])
[module(11411416 56B 1refs 18par 'threading')]

And there you go, the threading module.

And that's how you walk around the object graph. To finish analyzing this memory, I would probably poke at all the thread objects, and see what they are trying to accomplish. But mostly, the summary tells you that something is wrong. You shouldn't really be able to have 200k active threads doing real work. So probably you have something that is accidentally preserving threads that are no longer active.

Monday, November 16, 2009

Memory Debugging with Meliae

Background of Meliae 0.1.0

Earlier this year I started working on a new memory debugging program for python. I had originally tried to use heapy, but at the time it didn't support Windows, Mac, or 64-bit environments. (Which turned out to be all of my interesting platforms.) The other major problem is that I'm often debugging memory consumption of up to a GB of active data. While I think some of the former issues have been fixed, the latter is still a major issue for me.

So with the help of Michael Hudson, I started putting together a new structure. The code would be split into a scanner and a processor (loader). Such that you can interrupt a running process, dump the memory consumption to disk, and then analyze it in a separate process. (Often after the former has stopped.) The scanner can have a minimal memory profile, so even if your system is already swapping, you can dump out the memory info. (Robert Collins successfully dumped a 6GB memory profile, though analyzing that beast is still an issue.) The other advantage of this system, is that I don't have to play tricks with objects that represent the current state, like Guppy does with all sorts of crazy decorators.

In recent months, I've also focused on improving Bazaar's memory profile, which also meant improving memory profiling. Enough that I felt it was worth releasing the code. So officially Meliae 0.1.0 has been released. (For those wondering about the name, it is from Ash-Wood Nymph in Greek Mythology, aka it is just a fun name.)

Doing real work
So how does one actually use the program. Bazaar has a very nice ability, that you can use SIGQUIT (Ctrl+|) or SIGBREAK (Ctrl+Pause/Break) to drop into a debugger in the middle of a process to figure out what is going on. At that point, you can just:
from meliae import scanner
scanner.dump_all_objects('filename.json')
(There is an alternative scanner.dump_gc_objects() which has even lower memory profile, but will dump some objects more than once, creating a larger dump file.)

This creates a file describing all of the Python objects it was able to find along with their known size, references, and for some objects (strings, ints) their content. From there, you start another shell, and use:
>>> from meliae import loader
>>> om = loader.load('filename.json')
>>> s = om.summarize(); s

This dumps out something like:
Total 17916 objects, 96 types, Total size = 1.5MiB (1539583 bytes)
Index Count % Size % Cum Max Kind
0 701 3 546460 35 35 49292 dict
1 7138 39 414639 26 62 4858 str
2 208 1 94016 6 68 452 type
3 1371 7 93228 6 74 68 code
4 1431 7 85860 5 80 60 function
5 1448 8 59808 3 84 280 tuple
6 552 3 40760 2 86 684 list
7 56 0 29152 1 88 596 StgDict
8 2167 12 26004 1 90 12 int
9 619 3 24760 1 91 40 wrapper_descriptor
10 570 3 20520 1 93 36 builtin_function_or_method
...

Showing the top objects and what data they consume. This can often be revealing it itself. Do you have millions of tuples? One giant dict that is consuming a surprising amount of memory? (A dict with 200k entries is ~6MB on a 32-bit platform.)

There is more that can be done. You can run:
om.compute_referrers()

At this point, you can look at a single node, and find out what was referencing it. (So what was referencing that largest dict?)
>>> om[s.summaries[0].max_address]
MemObject(29351984, dict, 49292 bytes, 1578 refs [...], 1 referrers [26683840])

>>> om[26683840]
MemObject(29337264, function, format_string, 60 bytes, 6 refs...)

However, it also turns out that all 'classic' classes in Python indirect to their data via self.__dict__, which is a bit annoying to walk through. It also makes it looks like 'dict' is the #1 memory consumer, when actually it might be instances of Foo, which happen to use dicts. So you can use
om.collapse_instance_dicts()

Which will find all instances that seem to have trivial references to a __dict__, and then collapse it so that all references are directly from the instance, and all referenced objects then claim the instance as the referrer.

The above dump changes to:
>>> s = om.summarize(); s
Total 17701 objects, 96 types, Total size = 1.5MiB (1539583 bytes)
Index Count % Size % Cum Max Kind
0 7138 40 414639 26 26 4858 str
1 486 2 394632 25 52 49292 dict
2 208 1 94016 6 58 452 type
3 1371 7 93228 6 64 68 code
4 1431 8 85860 5 70 60 function
5 149 0 82844 5 75 556 ReadLineTextBuffer
6 93 0 65384 4 79 6312 module
7 1448 8 59808 3 83 280 tuple
8 552 3 40760 2 86 684 list
9 56 0 29152 1 88 596 StgDict
10 2167 12 26004 1 90 12 int

Which shows that ReadLineTextBuffer is actually a large consumer of memory.

Misc
There are other bits to explore, and improvements to be made. "scanner.get_recursive_size()" can be useful if you don't want to dump out a big file to analyze memory referenced from a given object (such as a cache). It doesn't give the whole picture, but can be useful in an interactive session.


Results
In the end, this code has enabled us to cut the memory consumption of Bazaar
roughly in half (for bzr branch). It also lets you see nice summaries
like this:

Total 2805995 objects, 276 types, Total size = 946.0MiB (991983819 bytes)
Index Count % Size % Cum Max Kind
0 1939090 69 916011611 92 92 5762600 str
1 9449 0 33069868 3 95 3145868 dict
2 132202 4 12506732 1 96 536 unicode
3 383436 13 7048652 0 97 20 bzrlib._static_tuple_c.StaticTuple
4 160027 5 5873744 0 98 304 tuple
5 5429 0 5185252 0 98 412236 list
6 62256 2 4482432 0 99 72 InventoryFile
7 148 0 1334032 0 99 1048692 set
8 2185 0 1214860 0 99 556 GroupCompressBlock
9 8003 0 992372 0 99 124 CHKInventoryDirectory
...


(Note that after seeing this, we changed the code to not cache as many strings in memory, and I managed to decrease memory consumption to about 1/3rd it once was for this operation.)

The code isn't perfect, but being able to get a view of where memory is going, and what objects are holding on to it, is a huge improvement over just being in the dark.

Monday, July 28, 2008

Last Week in Bazaar

Well, I'm late this week, so I'm officially marking this post as Last Week in Bazaar. In my defense, I got busy last Thursday, and then my cohort (Paul Hummer) flew off to New Zealand for a work-related sprint. So today, I (John Arbash Meinel, a developer on Bazaar) get to exercise full control over the content.


Keyword Expansion

People often request the ability to expand keywords, like they are used to in SVN and CVS. We've sort of postponed the implementation, because probably 90% of the time, it isn't really the right solution to the problem users are having. Also, they are kind of a mess in CVS anyway. Where I used to work we tried to use $Id$ style expansion, only to find out that they conflict on every attempt at merging, and we started working hard to strip them out of our files. In a distributed VCS, you usually merge at least an order-of-magnitude more often, which also tends to reveal this problem.

SVN at least works around the problem, in that when you commit, it actually strips the texts of their expanded keywords, so that the repository never stores the expanded form. And merges are also done on the non-expanded form. Which fixes that little problem. Though it introduces a couple others. Specifically, what you have on disk is not what sits in the repository, nor is it exactly what you will get out of a fresh checkout. The biggest reason is that if you commit revno 1354, it will update the tags of files that are touched. But if you checkout revno 1354 it will update the tags of *all* files. (I'm not positive on this, but I know there was a bug which was causing problems for people trying to do conversions. Because they couldn't quite find the right invocation to have 'update -r 1354' (from 1353) give the exact same tree as 'checkout -r 1354').

The other reason keyword expansion is not usually what you want, is because it expands only for the given file. If you make a commit to 5 other files, the *tree* is at revno 1359, but the file with your:

my_version = "$Version$";

Tag is still pointing at 1354. (Again, if 'svn update' would force all the tags to get re-expanded it might work correctly, though you run into performance problems expanding every keyword in every file on every update.) Bazaar has supported the bzr version-info command for a while, which lets you generate a version file (possibly from a template) which can store all the real details. Including the last-modified version for every file, whether any files in the working tree have been modified since commit, etc.

The only case that I've really heard a good reason for keyword expansion is for a Website. Where each individual file is spread out into the world. So having a little "last modified" at the bottom can be pretty convenient. You also don't tend to have a "build" process which lets you generate the version information at that time.

However, as Bazaar is meant to be a flexible system, Ian Clatworthy has done a wonderful job of adding the ability to support content munging via plugins. And has continued on to write a plugin specifically for expanding keywords.

http://bazaar-vcs.org/KeywordExpansion

So for all those people who feel they really need keyword expansion, look it up.I would imagine that once people get a good feel for it, and it matures a bit, it has a good chance to be brought into core code. Or at least make it into the release tarball as an "official" plugin.


Open Source, Python, and Counting My Blessings

Now onto something a bit more personal. This last week I had cause to re-visit an old library I had written, and try to get it up and running again. (Specifically, the project was pydcmtk, python wrappers for the Dicom Toolkit.)
It took me several hours times several days just to get it to build and run the test suite again. All without changing any of the code. It was simply a build-step problem.
Which revealed a couple wonderful things about my current work:

  1. I get to work in Python. Which is a nice language, flexible, and *doesn't* need a build step. Not having to deal with C/C++ and all the complexities of getting dependencies built, with the right version of the compiler, and the right flags to the compiler.
  2. Microsoft has a much harder time on their hands than Open Source does, at least when it comes to compatibility. Specifically, each version of their compiler comes with a different runtime. And code compiled for Visual Studio 7.1 doesn't like to work with the 8.0 objects nor the 9.0 objects. And they all have different msvcrtX.X.dll files. However, because the official method for getting your program to users is in binary (object) form, they have to provide ways to support your binary files for a long time. So in VS 8.0 they introduced a new step, which is to post-process your linked binaries with a manifest, declaring what runtimes they use. Further complicating this is that if you try to run a 8.0 compiled dll, it just gives an opaque "This process has tried to access the runtime incorrectly."
    Not realizing this, I spent a long time comparing the exact compiler flags with other examples to fix it. (The boost build tool, bjam, knows how to do it, but there was a line "if exists foo.manifest: do stuff", which I originally read as "if not exists foo.manifest: create the manifest.")
  3. Open source has generally handled the binary compatibility issue by punting and requesting software compatibility. And then you have a whole bunch of groups that spend their time recompiling everything for you (distributions like Ubuntu or Red Hat). And then they give you all the dependencies with a few simple commands (apt-get install zlib-dev dcmtk-dev boost-dev). On Windows, if you want to switch to developer mode, you generally have to grab the source code for all of those dependencies, and recompile them for your exact configuration.
    Software-level compatibility is *much* easier to handle. Not the least of which because if something becomes incompatible you can fix it. (I remember a Microsoft memory issue, where they had to switch in bug-for-bug compatibility because fixing it broke SimCity, how much better if they could have just patched SimCity.)
    Binary compatibility (for C/C++) means that you can't even add members to structs, because then the size changes and malloc starts failing (plus members are referenced by offset, so adding something in the *middle* is a big no-no).
    Source-level turns this way down into not removing things people are using. And, if something does change, with source-level you can even write a patch to fix the code. This does make it quite a bit harder for people who want to release binary-only packages, that they then don't have to modify for years. (Though when updating is a simple process, people are willing to do it more.)

1.6rc1 soon to come

We are working on putting the final polish to stacked branches. We are trying to release something that people can feel comfortable using right away, and there are a few tricks to get there. (For example, bzr has a general policy of always preserving the source format when you do 'bzr branch'. It helps maintain compatibility within a project that hasn't chosen to upgrade to a newer format yet. However if you do 'bzr branch --stacked' that indicates you want to use the new feature, so we have to work out logic to create an upgraded target at the right time. This also turns out to conflict a bit with bzr-svn, which had its own logic to trick 'bzr branch' into not copying the source format.)

You can already play with the Stacked Branches feature in the beta releases, but they'll appear much more polished in the final rc.

Friday, March 30, 2007

Java and Python

One thing that we are asked from time to time is if there is an Eclipse plugin for bzr. At the moment, there is a project which has been started: bzr-eclipse

It is still in the very early stages, but it seems there is enough interest, so I figured I would explore the space a bit.

One issue is trying to figure out how to communicate between bzr (written in Python) and Eclipse (written in Java).

One obvious method is to just write Java code which calls out to bzr the command line program, and then parses the string output from stdout and stderr. This can work, but bzr isn't especially scriptable. It can be scripted, but it is more focused on being something that is nice to use for a human than something that is easy to parse for a machine.

We have a much richer machine api in bzrlib the python library which is the guts of bzr. Wouldn't it be nice if we could get direct access to this rich API.

Well, there are two projects that I know of Jython and one I just heard about JEPP (Java Embedded Python).

Jython has the goal of running python code directly on the Java Virtual Machine. I'm not sure of everything that this entails, but my understanding is that it is basically writing a compiler that turns Python code into Java bytecodes. I have high hopes for this project, but at the moment it only supports Python 2.3 syntax (if you use the current beta). Unfortunately bzr is written with Python 2.4 syntax in mind. (We use decorators a lot and some generator comprehensions).

The other (major?) limitation is that Jython doesn't have a good way to support "os.chdir()". And while our general code doesn't actually use it, out test suite makes heavy use of "os.chdir()" to make sure that each test runs in isolation. Other limitations include not having a complete python standard library. Again, we use subprocess in the test suite when we want to ensure a clean run of bzr. We also use logging. There is also some concern about C extensions. At the moment, bzr is written in 100% python code, but as we finalize our data structures, we would like to implement any heavy processing loops in C/C++ (or possibly pyrex, which compiles to C).

But we could probably work around most of the missing functionality. The biggest thing is just Python 2.4 compatibility.

But this week I was exposed to Java Embedded Python or JEPP. Which takes the other approach. Rather than implementing the Python language in Java, just embed a CPython interpreter in a Java process.

This means you can use whatever CPython you have available on your system (2.3, 2.4, 2.5?). And you are sure to have access to the full standard library, extensions should never be a problem, etc.

The only real limitation of this approach is figuring out how well you can expose the embedded CPython interpreter. At a basic level, it isn't much different than calling 'python -c "do something"'. But it is possible to create a richer interaction between the CPython interpreter and the JVM, which is what JEPP is trying to do.

I played with JEPP today, and I think it is a really good start. It isn't functional enough yet that I would use it for a large project. But it seems almost there. At the moment it is able to return integers, floats, longs, and strings. But it isn't able to pass back and forth Python objects.

It does let you do stuff like:

Jep jep = new Jep(false, ".");
jep.runScript("a_python_script.py");

An the script can have quite a bit of logic. The script is run as '__main__', and the variables, functions, etc are in the running namespace. So you can do stuff like:

Object value = jep.getValue("variable");

or

Object ret = jep.invoke("a_function", "param1", 2, 3);

If "a_function" returns a "basic" type (int, long, float, str), then the returned Java Object is a Integer, Float, String, etc.

The only thing that doesn't work well is when the returned object is not a basic type. The code falls back to the catch-all, which converts everything to a string. I don't think this is the long term plan for the project, because they have a "PyObject" Java class.

I would expect the PyObject class to develop functions similar to Boost::Python's boost::python::object class.

I don't know if they will end up exposing as much of the api (slice is a nice convenience function, but logically maybe it shouldn't be on object), but ones like attr would certainly be useful. (As they also give you a way to call member functions, etc).

I know Boost does a lot of work behind the scenes with templates, and Java doesn't have the same functionality. I don't know if Java "Generics" are up to the task of PyObject(function).

Now I just have to figure out how to get commit notifications for a Sourceforge SVN project, so I can watch it evolve. :)

Tuesday, March 27, 2007

Test DRIVEN Development

For the Bazaar project we have a general goal that all code should be tested. We have an explicit development workflow that all new code must have associated tests before it can be merged into mainline.

Our latest release (0.15, rc3 is currently out the door, final should happen next week), introduces a new disk format, and a plethora of new tests. ('bzr selftest' in 0.14 has approx 4400 tests, and 5900 in 0.15). A lot of these are interface tests. Since we support multiple working tree, branch, and repository formats, we want to make sure that they all work the same way. (So only 1 tests is written, but it may be run against 4 or 5 different formats).

It means that we have a very good feeling that our code is doing what we expect it to (all of the major developers dogfood on the current mainline). However, it comes at a bit of a cost. In that running the full test suite gets slower and slower.

Further, I personally follow more of a 'test-after-development'. And I'm trying to get into the test driven development mindset. I don't know how I feel just yet, but I was reading this. And whether you agree with all of it, it makes it pretty clear how different the mindset can be. It goes through several iterations of testing, coding, and refactoring before it ends up anywhere I consider "realistic". And a lot of that comes at the 'refactoring' step, not at the coding step.

I have a glimpse at how it could be useful, as the idea is to have very small iterations. Such that it can be done in the 3-5 minute range. And every 3-5 minutes you should have a new test which passes. It means that you frequently have hard-coded defaults, since that is all the tests require at this point. But it might also help you design an interface, without worrying about actually implementing everything.

He also makes comments about keeping a TODO list. Which was part that made the most sense to me. Because you can't every write all the code fast enough to get all the ideas out of your head. So you keep a TODO so you don't forget, and also so you don't feel like you need to track down that path right now.

The other points that stuck with me are that most tests should be "unit tests". Which by his definition means they are memory only very narrow in scope. And that the test suite should be fast to run, because once it gets under a threshold (his comment was around 10 seconds, not minutes) then you can actually run all of them, all the time.

And since a development 'chunk' is supposed to be 3-5 minutes, it is pretty important that the test suite only take seconds to run. The 10s mark is actually reasonable, because it is about as long as you would be willing to give to that single task. Any longer and you are going to be context switching (email, more code, IRC, whatever).

The next level of test-size that he mentions is an "integration" test. I personally prefer the term "functional" test. But the idea is that a "unit" test should be testing the object (unit) under focus, and nothing else. Versus a functional test that might make use of other objects, and disk, database, whatever. And then the top level is doing an "end-to-end" test. Where you do the whole setup, test, and tear down. And these have purpose (like for conformance testing, or use case testing), but they really shouldn't be the bulk of your tests. If there is a problem here, it means your lower level tests are incomplete. They are good from a "the customer wants to be able to do 'X', this test shows that we do it the way they want" viewpoint.

I think I would like to try real TDD sometime, just to get the experience of it. I'll probably try it out on my next plugin, or some other small script I write. I have glimpses of how these sorts of things could be great. Often I'm not sure how to proceed while developing because the idea hasn't solidified in my head. One possibility here is "don't worry about it", create a test for what you think you want, stub out what you have to, and get something working.

Of course, the more I read, the more questions spring up. For example, there is a lot of discussion about test frameworks. Python comes with 'unittest', which is based on the general JUnit (or is it SUnit) framework. Where you subclass from a TestCase base class, and have a setUp(), and tearDown(), and a bunch of test_foo() tests.

But there is also nose and py.test, which both try to overcome unittest's limitations. And through reading about them, there is a discussion that python 3000 will actually have a slightly different default testing library. (For a sundry of technical and political reasons).

And then there is the mock versus stub debate. As near as I can tell, it seems to fall around how to create a unit test when the object under test depends on another object. And which method is more robust, easier to maintain, and easier to understand. That link lends some interesting thought about Mock objects. That instead of testing the state of objects, you are actually making an explicit assertion that the object being tested will make specific calls on the dependency.

I'm not settled on my decision, there. Because it feels like you are testing an exact implementation, rather than testing the side effect (interface). Some of what I read says "yes, that is what you are doing, and that is the point." I can understand testing side-effects. I guess part of it is how comfortable are you with having your test suite evolve. At least some tests need to be there to say that the interface hasn't changed since the previous release. (Or that a bug hasn't been reintroduced). If that edge case was tested by a particular test, and that test gets refactored, do you have confidence you didn't re-introduce the bug?

I guess you could have specific conventions about what tests are testing the current implementation, versus the overall interface of a function or class. I can understand that you want your test suite to evolve and stay maintainable. But at the other end, it is meant to test that things are conforming to some interface, so if you change the test suite, you are potentially breaking what you meant to maintain.

Maybe it just means you need several tiers of tests, each one less likely to be refactored.

Wednesday, March 14, 2007

Reading and Writing to Files ('r+', 'w+' mode) on Windows

It turns out that Windows has a small oddity when reading and writing to the a file. It is reported in the 'fopen' documentation at MSDN:
http://msdn2.microsoft.com/en-us/library/yeby3zcb(vs.71).aspx

The specific quote is:
When the "r+", "w+", or "a+" access type is specified, both reading and writing are allowed (the file is said to be open for "update"). However, when you switch between reading and writing, there must be an intervening fflush, fsetpos, fseek, or rewind operation. The current position can be specified for the fsetpos or fseek operation, if desired.
As an example, here is what you might do in python:
>>> f = open('test', 'wb+')
>>> f.write('initial text\n')
>>> f.close()
>>> f = open('test', 'rb+')
>>> f.read()
'initial text\n'
>>> f.write('this should go at the end\n')

On most platforms, that succeeds. But on Windows, if you don't do
>>> f.seek(0, 2) # Seek to the end of the file

before you call f.write(), you will get an IOError, with e.errno = 0. (Yeah, having an error of SUCCESS is a little hard to figure out).

Anyway, it took a while for me to figure out, so I figured I'd let other people know.

Thursday, February 22, 2007

Tuple creation speed

Just a small note for a python performance bit that I've found. If you have a list of things, and you want to turn some of them into a tuple, it is faster to do so using

out = (lst[0], lst[1], lst[2])

rather than

out = tuple(lst[0:3])

When I think closer about it, it makes sense. Since the list slicing [0:3] actually has to create a new list and populate it, which you then convert into a tuple.

I don't know if this scales to very large tuples (100 entries), but certainly for tuples up 5 entries it holds true.

To test it yourself, you can use python's timeit module.

% python -m timeit -s "lst = range(50000)" "x = tuple(lst[10:15])"
1000000 loops, best of 3: 1.12 usec per loop
% python -m timeit -s "lst = range(50000)" "x = (lst[10], lst[11], lst[12], lst[13], lst[14])"
1000000 loops, best of 3: 0.862 usec per loop

That's almost a 30% improvement for a list with 5 entries.