[Pyobjc-dev] Autopsy of a ktrace

[Ronald O. <ous...@ci...>]

I ran a ktrace on Examples/addressbook.py.

System: tibook 667Mhz, Python 2.3, PyObjC CVS-HEAD
Total runtime: 2.10 seconds (!)

The followig is based on the output of 'kdump -T', the relative times 
were calcuated using a awk-script. I wonder why Apple didn't add an 
option of this.

time 0.00s: Startup (in /usr/bin/env)
time 0.38s: open('addressbook.py')
time 0.47s: open('.../site.py')
time 0.56s: read(3, ...) -> contents of addressbook.py
time 0.58s: read(.../AddressBook/__init__.pyc)
time 0.59s: read(.../Foundation/__init__.pyc)
time 0.60s: read(.../objc/__init.pyc)
time 0.61s: open(.../objc/_objc.pyc)
time 0.61s: open(.../Version/2.3/Python)
time 0.63s: read(.../objc/_convenience.pyc)
time 0.65s: open(.../objc/_FoundationMapping.so)
time 0.66s: open(.../Foundation/_Foundation.so)
time 0.96s: Between here and previous open lots of references to 
Foundation.framework
time 0.97s: First referencee to AddressBook.framework
time 1.92s: Loaded support libraries, agian lots of references to 
various frameworks (including AppKit)
time 1.92s: First reference to AddressBook.data
time 2.10s: Done

The 'lots of references to ...' descriptions above refer to lines like 
those below, repeat many, many times (I've not counted them but it 
looks like hunderds of lines!!!):
2259 python 1.85493 CALL access(0xbfffd600,0x4)
2259 python 1.85496 NAMI "/System/Library/Frameworks/AppKit.framework"
2259 python 1.85501 RET access 0
2259 python 1.85526 CALL stat(0xbfffd600,0xbfffda10)
2259 python 1.85533 NAMI "/System/Library/Frameworks/AppKit.framework"
2259 python 1.85539 RET stat 0
2259 python 1.85544 CALL access(0xbfffd600,0x4)
2259 python 1.85547 NAMI "/System/Library/Frameworks/AppKit.framework"
2259 python 1.85552 RET access 0
2259 python 1.85576 CALL stat(0xbfffd600,0xbfffda10)
2259 python 1.85583 NAMI "/System/Library/Frameworks/AppKit.framework"
2259 python 1.85589 RET stat 0
2259 python 1.85592 CALL access(0xbfffd600,0x4)
2259 python 1.85596 NAMI "/System/Library/Frameworks/AppKit.framework"
2259 python 1.856 RET access 0

Obvious conclusion from the above: These 'strange' references eat up a 
lot of time, eliminating them would make this script significantly 
faster. But what causes this. My initial guess was: It wouldn't be 
objc_getClassList, would it?

Another obvious conclusing is that the startup of python itself is 
taking over half a second, which means we can never get as fast as 
Objective-C w.r.t. startup times (heck, a Objective-C version of 
addressbook.py runs in less time than Python takes to get to reading 
addressbook.py, I'll add the Objective-C version to the repository).

After modifying ObjC_GetClassList (in class-list.m) to try to use a 
static buffer of 1024 entries, and falling back to a malloc-ed buffer 
when that isn't good enough, I reran the ktrace and guess what: The 
number of lines in the output of kdump reduced from 23K to 22.5K lines 
so a guess objc_getClassList is doing something fishy. Sadly enough 
this didn't help with the runtime: This is still at 2.1 seconds. 
However: a simple Objective-C program doesn't confirm this: just 
calling objc_getClassList does not cause the strange sequence of calls 
I observed in the python script. But what else could be causing this?

Ronald