Chandler Start-up Timing

(MorgenSagen, 2 July 2004)

Recently I looked into where Chandler was spending all its time during start-up. I tried several methods including the hotshot profiler, and sprinkling calls to "time.time()" throughout the code. Hotshot is nice because it gives a comprehensive look at every method; however, it's very slow and skews the times (on my machine it was inflating them by a factor of about 3.6). I wrote a quick timing module which makes it easy to time certain sections of code (allowing you to label each section with a descriptive name), and get a simple report. That module is checked in as chandler/tools/timing.py.

Adding some timing calls to Parcel.py, Application.py, and the repository I see the following on a Dual-1.8 G5:

OnInit^?( ) is basically the time it takes to get from zero-to-Chandler, and includes all the other times. "Load parcels" (12.8 seconds) includes parsing all the parcel.xml files, creating repository items, and assigning values (literal and references) to those items' attributes. Essentially, of that 24 seconds, 20 are spent loading items into the repository and committing them to disk. If you already have a populated repository, the numbers become:

Bringing up Chandler is now around 9 seconds, with about 1.2 seconds scanning the XML files (the only thing the parcel loader needs to do with a populated repository). Interestingly, the time spent "outside" of parcel loading increases (from 4 seconds to 6.5) when you have a prepopulated repository, presumably because a bit more time is spent loading items out of the repository in this case.

Parcel loading is obviously a desirable area to speed up, so let's look more closely at it.

Of the 12 seconds spent in loading parcels, 3 are spent actually creating instances of python objects for those items, and 5.2 are spent assigning attributes to items. Inside those 3 seconds, all the object constructors get called; some take longer than others. Under the hood there ends up being thousands and thousands of calls to the repository API, specifically setAttributeValue( ) -- as Andi called it, "death by a thousand cuts".

I spoke to Andi about possible workarounds, of which there are (at least) two:

1) Rather than call the top level repository API to fill the items we're loading, call the repository ItemHandler^? instead, translating the parcel loader's SAX events into ones the ItemHandler^? understands. That way there are no calls to setAttributeValue( ), and the value and reference dictionaries are created behind the scenes and set on the item through _fillItem( ).

2) Use the repository Store API. This involves using a lower-level API, generating XML that the store natively understands. The benefit here is that many layers are avoided, and no python objects for those items need to be instantiated. There are some details which might be a problem -- cases where the parcel loader would have to hook up bi-directional references on items already in the repository. Andi would have to provide a means to do that. Our rough estimate was that this could speed up parcel loading by a factor of two. On a fast machine this could mean saving 6 seconds, perhaps; on a slower machine much more.

The one thing to keep in mind is that starting from an empty repository is something that no end user will likely do -- we will ship the product with a preloaded repository.

Warm Start Tests

(NickParlante, 13 July 2004)

I did a little poking around with time.clock() to get a feel for warm-start performance using June-30 sources (I did this before I saw Morgen's stuff above, but hopefully it still has some value). I put calls in Chandler.py and Application.py to trace the steps of a warm startup until the window shows up using a repository where I used "generate items" to make a little data. Here's the percentage times I found, in chronological order at startup...

• Chandler.py imports at the top of the file -- 31%
• All the rest of the time is in wxApplication onInit...
• Setting the splash screen, the locale, and the parcel dir -- 0% (basically free!)
• Open repository -- 9%
• Load parcels -- 18%
• Start notifications -- 5%
• Load main view (up to self.mainFrame.Show()) -- 36%

I did the tests on a fast G5 and my old ibook and the percentages were basically the same. Below are the profiles for the above startup the first sorted by time within each python method (including whatever C it calls), and the second sorted by cumulative time. It's all mostly over my head, but I can make a couple observations...

• What the heck is going on with those imports taking so much time, something about wx?
• Most of the time is in the repository -- Item, XMLRepository etc.. It's obviously a complex, sophisticated system. To see what's really going on, someone who understands the repository implementation will need to look at the paths that the app stresses at startup time to think about optimizations.
• I figured out one thing: why are there so many calls to Item.py __setattr__ ? It's because getAttributeVAlue() does a

  self._lastAccess = Item._countAccess()

  which makes for a lot of __setattr__. Of course that code looks right for the general case, but one can imagine hacking in something cheaper just for startup.
• XMLRepository start/abort transaction sticks out a bit. One can imagine hacking in something for the startup case, such as just having one big transaction to cover the whole thing. Also the proliferation of berkeleydb log files suggests that something about transactions could be tuned.

Top expensive methods...

         354093 function calls (336972 primitive calls) in 12.040 CPU seconds

   Ordered by: internal time
   List reduced from 2020 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
9119/6086    0.410    0.000    3.120    0.001 Item.py:425(getAttributeValue)
     1130    0.400    0.000    1.160    0.001 DBContainer.py:445(readName)
        1    0.390    0.390    0.430    0.430 XMLRepository.py:105(open)
      897    0.360    0.000    1.060    0.001 DBContainer.py:163(loadRef)
    17897    0.350    0.000    0.580    0.000 ThreadLocal.py:39(_getCurrentThreadLocals)
16936/16493    0.340    0.000    0.620    0.000 Item.py:144(__setattr__)
     2691    0.330    0.000    0.710    0.000 XMLRepository.py:456(startTransaction)
        6    0.330    0.055    0.470    0.078 core.py:5830(Show)
     2412    0.310    0.000    0.650    0.000 XMLRepository.py:476(abortTransaction)
  338/187    0.260    0.001    7.390    0.040 libxml2.py:4680(parseChunk)
    17915    0.230    0.000    0.230    0.000 threading.py:609(currentThread)
    13496    0.180    0.000    0.180    0.000 UUID.py:60(__hash__)
3556/3525    0.160    0.000    1.230    0.000 Attribute.py:28(getAspect)
3291/2935    0.160    0.000    6.020    0.002 Kind.py:78(getAttribute)
3994/3419    0.150    0.000    3.730    0.001 ItemHandler.py:68(endElement)
      338    0.150    0.000    0.160    0.000 libxml2.py:1375(createPushParser)
7290/7092    0.150    0.000    1.380    0.000 LinkedMap.py:203(get)
    10224    0.150    0.000    0.590    0.000 XMLRepository.py:489(_getTxn)
      113    0.150    0.001    0.180    0.002 dbxml.py:213(next)
     2410    0.150    0.000    0.280    0.000 DBContainer.py:73(cursor)
    13062    0.150    0.000    0.580    0.000 ThreadLocal.py:21(__getattr__)
4460/2622    0.140    0.000    4.160    0.002 ItemRef.py:134(other)
3760/3387    0.140    0.000    3.180    0.001 Item.py:1594(getItemChild)
    11458    0.140    0.000    0.140    0.000 Item.py:2029(_countAccess)
3076/3072    0.140    0.000    2.330    0.001 Item.py:768(getValue)
     1078    0.130    0.000    0.510    0.000 LinkedMap.py:105(__setitem__)
 1788/683    0.130    0.000    6.570    0.010 RepositoryView.py:224(find)
        6    0.130    0.022    0.130    0.022 dbxml.py:90(queryWithXPath)
     5808    0.130    0.000    0.130    0.000 UUID.py:22(__init__)
3076/3072    0.120    0.000    1.950    0.001 ItemRef.py:706(get)
3994/2853    0.110    0.000    4.690    0.002 ItemHandler.py:48(startElement)
2339/2313    0.100    0.000    0.350    0.000 Item.py:1154(setDirty)
  635/431    0.100    0.000    1.910    0.004 ItemRef.py:664(_load)
1022/1008    0.100    0.000    0.440    0.000 RepositoryView.py:487(__getitem__)
2829/2828    0.100    0.000    0.240    0.000 Repository.py:180(getCurrentView)
  746/595    0.100    0.000    1.270    0.002 ItemRef.py:564(__setitem__)
      897    0.100    0.000    1.270    0.001 XMLRepositoryView.py:384(_loadRef)
     4830    0.090    0.000    0.290    0.000 XMLRepository.py:497(_setTxn)
3317/3297    0.090    0.000    2.840    0.001 Kind.py:67(resolve)
      273    0.090    0.000    0.120    0.000 dbxml.py:88(getDocument)

Top cumulative time methods...

         354093 function calls (336972 primitive calls) in 12.040 CPU seconds

   Ordered by: cumulative time
   List reduced from 2020 to 40 due to restriction <40>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.070    0.070   12.040   12.040 core.py:4785(_BootstrapApp)
        1    0.000    0.000   12.040   12.040 profile:0(main())
        1    0.000    0.000   12.040   12.040 core.py:5004(__init__)
        1    0.000    0.000   12.040   12.040 Chandler.py:37(main)
        1    0.000    0.000   12.040   12.040 <string>:1(?)
        1    0.010    0.010   11.970   11.970 Application.py:137(OnInit)
  338/153    0.090    0.000    7.770    0.051 RepositoryView.py:721(_loadDoc)
  338/187    0.010    0.000    7.540    0.040 RepositoryView.py:422(_loadItemDoc)
  338/187    0.010    0.000    7.530    0.040 XMLRepository.py:432(parseDoc)
  338/187    0.020    0.000    7.520    0.040 XMLRepository.py:272(parseDoc)
  338/187    0.260    0.001    7.390    0.040 libxml2.py:4680(parseChunk)
 1788/683    0.130    0.000    6.570    0.010 RepositoryView.py:224(find)
3291/2935    0.160    0.000    6.020    0.002 Kind.py:78(getAttribute)
3994/2853    0.110    0.000    4.690    0.002 ItemHandler.py:48(startElement)
  160/103    0.010    0.000    4.640    0.045 RepositoryView.py:775(_loadItem)
4460/2622    0.140    0.000    4.160    0.002 ItemRef.py:134(other)
4460/2622    0.080    0.000    4.030    0.002 ItemRef.py:63(getOther)
   118/83    0.000    0.000    3.970    0.048 ItemRef.py:296(_loadItem)
  164/127    0.000    0.000    3.920    0.031 Item.py:1759(find)
3994/3419    0.150    0.000    3.730    0.001 ItemHandler.py:68(endElement)
  393/337    0.010    0.000    3.620    0.011 LinkedMap.py:235(__iter__)
1549/1131    0.030    0.000    3.410    0.003 ItemHandler.py:492(getAttribute)
  327/271    0.000    0.000    3.240    0.012 ItemRef.py:560(__getitem__)
3760/3387    0.140    0.000    3.180    0.001 Item.py:1594(getItemChild)
     43/1    0.000    0.000    3.150    3.150 Block.py:36(render)
  353/295    0.020    0.000    3.130    0.011 RepositoryView.py:800(_loadChild)
9119/6086    0.410    0.000    3.120    0.001 Item.py:425(getAttributeValue)
  150/111    0.010    0.000    3.090    0.028 Query.py:43(run)
  782/684    0.020    0.000    3.070    0.004 ItemHandler.py:329(attributeStart)
        6    0.000    0.000    2.990    0.498 XMLRepositoryView.py:78(queryItems)
3317/3297    0.090    0.000    2.840    0.001 Kind.py:67(resolve)
        1    0.010    0.010    2.700    2.700 Parcel.py:545(loadParcels)
        1    0.000    0.000    2.530    2.530 Views.py:108(onSetActiveView)
        1    0.010    0.010    2.420    2.420 Parcel.py:269(__scanParcels)
3076/3072    0.140    0.000    2.330    0.001 Item.py:768(getValue)
2521/1884    0.050    0.000    2.290    0.001 Item.py:131(__getattr__)
        1    0.000    0.000    2.120    2.120 MenuBlocks.py:12(rebuildMenus)
  241/165    0.020    0.000    2.110    0.013 Kind.py:174(_inheritAttribute)
        1    0.010    0.010    2.020    2.020 MenuBlocks.py:19(buildMenuList)
3076/3072    0.120    0.000    1.950    0.001 ItemRef.py:706(get)