Use Case

1. Start Chandler (existing repository).
2. Go to calendar collection/view.
3. Select week layout from layout selector.
4. Double click in view on a time with no events. (creates a new item, slow response)
5. Double click somewhere else in the view on a time with no events. (creates a second new item, slow response)
6. Quit chandler

Summary

On a relatively fast machine, we get ~2 sec response time at #4 and ~1 sec response time at #5. The ultimate goal is for the response to be < .1 sec on modern hardware.

The majority of the time is spent in commit, and the majority of that time is spent in calls to dbxml's putDocument. putDocument is called once for each dirtied item. Another observation is that more items are dirty than we might expect. At step #4, commit writes out ~50 items. Step #5 writes out slightly fewer items. If we look at what items are committed in these instances, we see that we commit a lot of blocks, the calendar item collection, and every item in the calendar item collection. In Step #5, we don't have as many dirty blocks, so it is faster.

Next steps:

• look at ways to not dirty the item collection and contents (Bug#2042)
• look at ways to not dirty as many blocks (Bug#2043)
• look at avoiding calling commit in this instance (call refresh instead -- currently this causes a problem where the new item is not found by the query)
• look at ways to speed up commit/saveItem/putDocument (note, Andi has some ideas on how to avoid calling putDocument when literals are not modified.)

Logging info

With an existing repository, this use case results in 4 calls to commit. The second commit happens at #4, the third commit at #5. THe last commit is called when the app quits. From the log (adding a logging call before every _saveItem in commit):

2004-09-28 15:47:10,246 INFO committing item: <Manager: manager 922b09fc-119b-11d9-b57a-00065bdcfd19>
2004-09-28 15:47:10,341 INFO <XMLRepositoryView: MainThread> committed 1 items (431 bytes) in 0:00:00.094000
2004/09/28 15:47 Pacific Daylight Time [-] Enabling Multithreading.
2004/09/28 15:47 Pacific Daylight Time [-] starting waker
2004-09-28 15:47:22,730 INFO committing item: []
2004-09-28 15:47:22,763 INFO committing item: <ItemCollection: sidebarItemCollection 9b7b398c-119b-11d9-bb7a-00065bdcfd19>
2004-09-28 15:47:22,793 INFO committing item: <SplitterWindow: AllView 9ae2a30c-119b-11d9-ba07-00065bdcfd19>
2004-09-28 15:47:22,855 INFO committing item: <SplitterWindow: InView 9ae2a30c-119b-11d9-ba0a-00065bdcfd19>
2004-09-28 15:47:22,888 INFO committing item: <SplitterWindow: OutView 9ae50566-119b-11d9-ba0c-00065bdcfd19>
2004-09-28 15:47:22,950 INFO committing item: <SplitterWindow: CalendarView 9ae50566-119b-11d9-ba0f-00065bdcfd19>
2004-09-28 15:47:23,013 INFO committing item: <Sidebar: Sidebar 9b84c2f4-119b-11d9-bb84-00065bdcfd19>
2004-09-28 15:47:23,091 INFO committing item: <ItemCollection: calendarItemCollection 9aa2438e-119b-11d9-b9a9-00065bdcfd19>
2004-09-28 15:47:23,121 INFO committing item: <LayoutChooser: CalendarSummary 9acacb88-119b-11d9-b9ec-00065bdcfd19>
2004-09-28 15:47:23,200 INFO committing item: <MonthBlock: SummaryMonth 9ab091aa-119b-11d9-b9d7-00065bdcfd19>
2004-09-28 15:47:23,278 INFO committing item: <Table: CalendarTable 9acf903c-119b-11d9-b9ed-00065bdcfd19>
2004-09-28 15:47:23,309 INFO committing item: <CalendarEvent: 1665b578-119c-11d9-fd04-00065bdcfd19>
2004-09-28 15:47:23,355 INFO committing item: <CalendarEvent: 6580188a-119f-11d9-83e0-00065bdcfd19>
2004-09-28 15:47:23,371 INFO committing item: <CalendarEvent: c882c35a-119b-11d9-c085-00065bdcfd19>
2004-09-28 15:47:23,403 INFO committing item: <CalendarEvent: 1920467a-119c-11d9-fd04-00065bdcfd19>
2004-09-28 15:47:23,434 INFO committing item: <CalendarEvent: 6126ae5c-119f-11d9-83df-00065bdcfd19>
2004-09-28 15:47:23,466 INFO committing item: <CalendarEvent: cda210b6-119b-11d9-c086-00065bdcfd19>
2004-09-28 15:47:23,480 INFO committing item: <DetailRoot: DetailRoot 9e5e5288-119b-11d9-bed8-00065bdcfd19>
2004-09-28 15:47:23,543 INFO committing item: <ContentItemDetail: 9e5e5288-119b-11d9-bedd-00065bdcfd19>
2004-09-28 15:47:23,575 INFO committing item: <LabeledTextAttributeBlock: 9e67dbf0-119b-11d9-bf0b-00065bdcfd19>
2004-09-28 15:47:23,621 INFO committing item: ['9VukEwhCN7pbXB00prTfQp', '9VwJe8hCN7pbXD00prTfQp', '9VwJe8hCN7pbXG00prTfQp']
2004-09-28 15:47:23,716 INFO committing item: <StaticToFromText: 9e63173c-119b-11d9-bef2-00065bdcfd19>
2004-09-28 15:47:23,793 INFO committing item: <ToEditField: 9e63173c-119b-11d9-bef5-00065bdcfd19>
2004-09-28 15:47:23,855 INFO committing item: <ToAndFromBlock: 9e60b4e2-119b-11d9-bef0-00065bdcfd19>
2004-09-28 15:47:23,903 INFO committing item: <StaticToFromText: 9e63173c-119b-11d9-befb-00065bdcfd19>
2004-09-28 15:47:23,966 INFO committing item: <FromEditField: 9e657996-119b-11d9-befd-00065bdcfd19>
2004-09-28 15:47:24,028 INFO committing item: <ToAndFromBlock: 9e63173c-119b-11d9-bef8-00065bdcfd19>
2004-09-28 15:47:24,138 INFO committing item: <ToAndFromBlock: 9e60b4e2-119b-11d9-beed-00065bdcfd19>
2004-09-28 15:47:24,184 INFO committing item: <ContactFullNameEditField: 9e657996-119b-11d9-bf06-00065bdcfd19>
2004-09-28 15:47:24,230 INFO committing item: <ContactFullNameBlock: 9e657996-119b-11d9-bf00-00065bdcfd19>
2004-09-28 15:47:24,293 INFO committing item: <StaticRedirectAttribute: 9e67dbf0-119b-11d9-bf0e-00065bdcfd19>
2004-09-28 15:47:24,355 INFO committing item: <EditHeadlineRedirectAttribute: 9e67dbf0-119b-11d9-bf11-00065bdcfd19>
2004-09-28 15:47:24,418 INFO committing item: <StaticEmailAddressAttribute: 9e6a3e4a-119b-11d9-bf16-00065bdcfd19>
2004-09-28 15:47:24,466 INFO committing item: <EditEmailAddressAttribute: 9e6a3e4a-119b-11d9-bf19-00065bdcfd19>
2004-09-28 15:47:24,559 INFO committing item: <EmailAddressBlock: 9e67dbf0-119b-11d9-bf14-00065bdcfd19>
2004-09-28 15:47:24,621 INFO committing item: <DateTimeBlock: 9e6ca0a4-119b-11d9-bf21-00065bdcfd19>
2004-09-28 15:47:24,668 INFO committing item: <KindLabel: 9e6ca0a4-119b-11d9-bf24-00065bdcfd19>
2004-09-28 15:47:24,746 INFO committing item: <StaticTimeAttribute: 9e6f02fe-119b-11d9-bf29-00065bdcfd19>
2004-09-28 15:47:24,778 INFO committing item: <EditTimeAttribute: 9e6f02fe-119b-11d9-bf2c-00065bdcfd19>
2004-09-28 15:47:24,855 INFO committing item: <CalendarEventBlock: 9e6f02fe-119b-11d9-bf26-00065bdcfd19>
2004-09-28 15:47:24,903 INFO committing item: <StaticDurationAttribute: 9e6f02fe-119b-11d9-bf32-00065bdcfd19>
2004-09-28 15:47:24,966 INFO committing item: <EditDurationAttribute: 9e716558-119b-11d9-bf34-00065bdcfd19>
2004-09-28 15:47:25,013 INFO committing item: <CalendarEventBlock: 9e6f02fe-119b-11d9-bf2f-00065bdcfd19>
2004-09-28 15:47:25,075 INFO committing item: <NoteBody: 9e716558-119b-11d9-bf37-00065bdcfd19>
2004-09-28 15:47:25,121 INFO committing item: <SendShareButton: 9e716558-119b-11d9-bf3a-00065bdcfd19>
2004-09-28 15:47:25,200 INFO committing item: <MainView: MainView 9bc05dbe-119b-11d9-bb8b-00065bdcfd19>
2004-09-28 15:47:25,246 INFO committing item: <SplitterWindow: MainSplitter 9b87254e-119b-11d9-bb86-00065bdcfd19>
2004-09-28 15:47:25,293 INFO committing item: <Item: contentitems 9f5b0bcc-119b-11d9-c078-00065bdcfd19>
2004-09-28 15:47:25,293 INFO committing item: <CalendarEvent (new): 5c247cf8-11a0-11d9-f2be-00065bdcfd19>
2004-09-28 15:47:25,341 INFO committing item: me <osafuser@code-bear.com>
2004-09-28 15:47:25,403 INFO <XMLRepositoryView: MainThread> committed 50 items (95798 bytes) in 0:00:02.672000
2004-09-28 15:47:27,513 INFO committing item: <ItemCollection: calendarItemCollection 9aa2438e-119b-11d9-b9a9-00065bdcfd19>
2004-09-28 15:47:27,543 INFO committing item: <CalendarEvent: 1665b578-119c-11d9-fd04-00065bdcfd19>
2004-09-28 15:47:27,543 INFO committing item: <CalendarEvent: 6580188a-119f-11d9-83e0-00065bdcfd19>
2004-09-28 15:47:27,575 INFO committing item: <CalendarEvent: c882c35a-119b-11d9-c085-00065bdcfd19>
2004-09-28 15:47:27,591 INFO committing item: <CalendarEvent: 1920467a-119c-11d9-fd04-00065bdcfd19>
2004-09-28 15:47:27,621 INFO committing item: <CalendarEvent: 6126ae5c-119f-11d9-83df-00065bdcfd19>
2004-09-28 15:47:27,668 INFO committing item: <CalendarEvent: cda210b6-119b-11d9-c086-00065bdcfd19>
2004-09-28 15:47:27,668 INFO committing item: <CalendarEvent: 5c247cf8-11a0-11d9-f2be-00065bdcfd19>
2004-09-28 15:47:27,716 INFO committing item: <Item: contentitems 9f5b0bcc-119b-11d9-c078-00065bdcfd19>
2004-09-28 15:47:27,763 INFO committing item: <CalendarEvent (new): 5f3c09b0-11a0-11d9-f2bf-00065bdcfd19>
2004-09-28 15:47:27,763 INFO committing item: me <osafuser@code-bear.com>
2004-09-28 15:47:27,793 INFO committing item: <MonthBlock: SummaryMonth 9ab091aa-119b-11d9-b9d7-00065bdcfd19>
2004-09-28 15:47:27,855 INFO committing item: <DetailRoot: DetailRoot 9e5e5288-119b-11d9-bed8-00065bdcfd19>
2004-09-28 15:47:27,888 INFO committing item: <ContentItemDetail: 9e5e5288-119b-11d9-bedd-00065bdcfd19>
2004-09-28 15:47:27,950 INFO committing item: <LabeledTextAttributeBlock: 9e67dbf0-119b-11d9-bf0b-00065bdcfd19>
2004-09-28 15:47:28,043 INFO <XMLRepositoryView: MainThread> committed 15 items (29097 bytes) in 0:00:00.531000
2004-09-28 15:47:29,730 INFO committing item: <ItemCollection: calendarItemCollection 9aa2438e-119b-11d9-b9a9-00065bdcfd19>
2004/09/28 15:47 Pacific Daylight Time [-] Main loop terminated.
2004-09-28 15:47:29,778 INFO committing item: <CalendarEvent: 1665b578-119c-11d9-fd04-00065bdcfd19>
2004-09-28 15:47:29,809 INFO committing item: <CalendarEvent: 6580188a-119f-11d9-83e0-00065bdcfd19>
2004-09-28 15:47:29,809 INFO committing item: <CalendarEvent: c882c35a-119b-11d9-c085-00065bdcfd19>
2004-09-28 15:47:29,871 INFO committing item: <CalendarEvent: 1920467a-119c-11d9-fd04-00065bdcfd19>
2004-09-28 15:47:29,871 INFO committing item: <CalendarEvent: 6126ae5c-119f-11d9-83df-00065bdcfd19>
2004-09-28 15:47:29,918 INFO committing item: <CalendarEvent: cda210b6-119b-11d9-c086-00065bdcfd19>
2004-09-28 15:47:29,918 INFO committing item: <CalendarEvent: 5c247cf8-11a0-11d9-f2be-00065bdcfd19>
2004-09-28 15:47:29,966 INFO committing item: <CalendarEvent: 5f3c09b0-11a0-11d9-f2bf-00065bdcfd19>
2004-09-28 15:47:30,013 INFO committing item: <DetailRoot: DetailRoot 9e5e5288-119b-11d9-bed8-00065bdcfd19>
2004-09-28 15:47:30,043 INFO committing item: <ContentItemDetail: 9e5e5288-119b-11d9-bedd-00065bdcfd19>
2004-09-28 15:47:30,138 INFO committing item: ['9VukEwhCN7pbXB00prTfQp', '9VwJe8hCN7pbXD00prTfQp', '9VwJe8hCN7pbXG00prTfQp']
2004-09-28 15:47:30,184 INFO committing item: <MailMessageButton: 9e5e5288-119b-11d9-bee5-00065bdcfd19>
2004-09-28 15:47:30,246 INFO committing item: <TaskStamp: 9e60b4e2-119b-11d9-bee7-00065bdcfd19>
2004-09-28 15:47:30,309 INFO committing item: <CalendarStamp: 9e60b4e2-119b-11d9-beea-00065bdcfd19>
2004-09-28 15:47:30,371 INFO committing item: <ToAndFromBlock: 9e60b4e2-119b-11d9-beed-00065bdcfd19>
2004-09-28 15:47:30,450 INFO committing item: <ToAndFromBlock: 9e60b4e2-119b-11d9-bef0-00065bdcfd19>
2004-09-28 15:47:30,513 INFO committing item: <StaticToFromText: 9e63173c-119b-11d9-bef2-00065bdcfd19>
2004-09-28 15:47:30,591 INFO committing item: <ToEditField: 9e63173c-119b-11d9-bef5-00065bdcfd19>
2004-09-28 15:47:30,605 INFO committing item: <ToAndFromBlock: 9e63173c-119b-11d9-bef8-00065bdcfd19>
2004-09-28 15:47:30,684 INFO committing item: <StaticToFromText: 9e63173c-119b-11d9-befb-00065bdcfd19>
2004-09-28 15:47:30,855 INFO committing item: <FromEditField: 9e657996-119b-11d9-befd-00065bdcfd19>
2004-09-28 15:47:30,918 INFO committing item: <ContactFullNameBlock: 9e657996-119b-11d9-bf00-00065bdcfd19>
2004-09-28 15:47:30,966 INFO committing item: <StaticText: 9e657996-119b-11d9-bf03-00065bdcfd19>
2004-09-28 15:47:31,028 INFO committing item: <ContactFullNameEditField: 9e657996-119b-11d9-bf06-00065bdcfd19>
2004-09-28 15:47:31,091 INFO committing item: <ContentItemDetail: 9e657996-119b-11d9-bf09-00065bdcfd19>
2004-09-28 15:47:31,153 INFO committing item: <LabeledTextAttributeBlock: 9e67dbf0-119b-11d9-bf0b-00065bdcfd19>
2004-09-28 15:47:31,216 INFO committing item: <StaticRedirectAttribute: 9e67dbf0-119b-11d9-bf0e-00065bdcfd19>
2004-09-28 15:47:31,278 INFO committing item: <EditHeadlineRedirectAttribute: 9e67dbf0-119b-11d9-bf11-00065bdcfd19>
2004-09-28 15:47:31,325 INFO committing item: <EmailAddressBlock: 9e67dbf0-119b-11d9-bf14-00065bdcfd19>
2004-09-28 15:47:31,403 INFO committing item: <StaticEmailAddressAttribute: 9e6a3e4a-119b-11d9-bf16-00065bdcfd19>
2004-09-28 15:47:31,450 INFO committing item: <EditEmailAddressAttribute: 9e6a3e4a-119b-11d9-bf19-00065bdcfd19>
2004-09-28 15:47:31,513 INFO committing item: <ContentItemDetail: 9e6ca0a4-119b-11d9-bf1b-00065bdcfd19>
2004-09-28 15:47:31,559 INFO committing item: <StaticText: 9e6ca0a4-119b-11d9-bf1e-00065bdcfd19>
2004-09-28 15:47:31,621 INFO committing item: <DateTimeBlock: 9e6ca0a4-119b-11d9-bf21-00065bdcfd19>
2004-09-28 15:47:31,684 INFO committing item: <KindLabel: 9e6ca0a4-119b-11d9-bf24-00065bdcfd19>
2004-09-28 15:47:31,746 INFO committing item: <CalendarEventBlock: 9e6f02fe-119b-11d9-bf26-00065bdcfd19>
2004-09-28 15:47:31,809 INFO committing item: <StaticTimeAttribute: 9e6f02fe-119b-11d9-bf29-00065bdcfd19>
2004-09-28 15:47:31,855 INFO committing item: <EditTimeAttribute: 9e6f02fe-119b-11d9-bf2c-00065bdcfd19>
2004-09-28 15:47:31,918 INFO committing item: <CalendarEventBlock: 9e6f02fe-119b-11d9-bf2f-00065bdcfd19>
2004-09-28 15:47:31,996 INFO committing item: <StaticDurationAttribute: 9e6f02fe-119b-11d9-bf32-00065bdcfd19>
2004-09-28 15:47:32,075 INFO committing item: <EditDurationAttribute: 9e716558-119b-11d9-bf34-00065bdcfd19>
2004-09-28 15:47:32,138 INFO committing item: <NoteBody: 9e716558-119b-11d9-bf37-00065bdcfd19>
2004-09-28 15:47:32,168 INFO committing item: <SendShareButton: 9e716558-119b-11d9-bf3a-00065bdcfd19>
2004-09-28 15:47:32,230 INFO <XMLRepositoryView: MainThread> committed 44 items (85584 bytes) in 0:00:02.500000

Hotshot profile of CollectionCanvas\CalendarCanvas OnCreateItem()

The profiles are created from the handler that gets called when the double click is recognized. This first profile is from step #4. Both profiles are from my xp box at home, using a wx2529 build. (I happened to play around with this before the migration was pulled into the main build). I put the profile code in CollectionCanvas' mouse handler, calling it instead of OnCreateItem().

         167531 function calls (164442 primitive calls) in 18.681 CPU seconds

   Ordered by: internal time, call count
   List reduced from 647 to 50 due to restriction <50>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       56   11.707    0.209   11.707    0.209 dbxml.py:82(putDocument)
      121    1.615    0.013    1.631    0.013 dbcontainer.py:63(put)
     1126    0.338    0.000    0.662    0.001 dbcontainer.py:559(readName)
4750/4418    0.273    0.000    1.155    0.000 item.py:513(getAttributeValue)
     1812    0.161    0.000    0.161    0.000 sax.py:80(startElement)
5589/5372    0.146    0.000    0.222    0.000 item.py:151(__setattr__)
     4680    0.130    0.000    0.333    0.000 xmlrepository.py:466(_getTxn)
     6944    0.127    0.000    0.194    0.000 threadlocal.py:39(_getCurrentThrea
dLocals)
        1    0.116    0.116    0.116    0.116 xmlrepository.py:444(commitTransac
tion)
  607/555    0.085    0.000    0.669    0.001 itemhandler.py:556(xmlValue)
     5648    0.085    0.000    0.244    0.000 threadlocal.py:21(__getattr__)
     4914    0.076    0.000    0.076    0.000 item.py:2326(_countAccess)
2563/2511    0.075    0.000    0.358    0.000 attribute.py:28(getAspect)
      387    0.075    0.000    0.369    0.001 dbcontainer.py:259(loadRef)
     1573    0.073    0.000    0.181    0.000 dbcontainer.py:78(cursor)
     5410    0.072    0.000    0.072    0.000 item.py:1211(hasAttributeValue)
     2459    0.072    0.000    0.402    0.000 linkedmap.py:80(_get)
       56    0.068    0.001    1.822    0.033 values.py:160(_xmlValues)
     6944    0.067    0.000    0.067    0.000 threading.py:609(currentThread)
1059/1013    0.067    0.000    2.230    0.002 kind.py:121(getAttribute)
     1577    0.067    0.000    0.223    0.000 xmlrepository.py:433(startTransact
ion)
2801/2751    0.064    0.000    0.894    0.000 itemref.py:136(other)
     1160    0.060    0.000    0.060    0.000 uuid.py:22(__init__)
     2937    0.060    0.000    0.081    0.000 itemref.py:43(getItem)
2801/2751    0.059    0.000    0.751    0.000 itemref.py:54(getOther)
     7634    0.059    0.000    0.059    0.000 uuid.py:60(__hash__)
1585/1505    0.057    0.000    0.858    0.001 linkedmap.py:211(get)
    55/28    0.056    0.001    1.212    0.043 libxml2.py:4680(parseChunk)
     1147    0.055    0.000    1.491    0.001 kind.py:110(resolve)
2587/2528    0.053    0.000    0.857    0.000 item.py:141(__getattr__)
     1018    0.051    0.000    0.434    0.000 itemref.py:923(get)
      564    0.050    0.000    0.249    0.000 types.py:504(_fieldXML)
      932    0.047    0.000    0.079    0.000 repositoryview.py:517(__getitem__)

     3630    0.046    0.000    0.046    0.000 item.py:1245(isNew)
      647    0.045    0.000    0.180    0.000 xmlrepository.py:453(abortTransact
ion)
     5714    0.044    0.000    0.044    0.000 item.py:2283(_loadItem)
  342/341    0.043    0.000    0.162    0.000 linkedmap.py:109(__setitem__)
     1907    0.043    0.000    0.895    0.000 linkedmap.py:322(__iter__)
     1018    0.042    0.000    0.565    0.001 item.py:857(getValue)
       28    0.041    0.001    0.048    0.002 dbxml.py:213(next)
  550/112    0.040    0.000    0.455    0.004 kind.py:306(isKindOf)
     1101    0.039    0.000    0.114    0.000 itemref.py:918(_getRef)
     1907    0.039    0.000    0.397    0.000 linkedmap.py:327(iterkeys)
  608/597    0.037    0.000    0.544    0.001 itemhandler.py:66(endElement)
     1137    0.036    0.000    0.036    0.000 values.py:98(_getFlags)
     1067    0.036    0.000    0.420    0.000 itemref.py:761(__getitem__)
     1812    0.035    0.000    0.035    0.000 sax.py:96(endElement)
      647    0.034    0.000    0.497    0.001 xmlrefdict.py:340(resolveAlias)
     1880    0.033    0.000    0.199    0.000 itemref.py:1187(iterkeys)
      329    0.032    0.000    0.365    0.001 xmlrefdict.py:36(_loadRef)


         167531 function calls (164442 primitive calls) in 18.681 CPU seconds

   Ordered by: call count
   List reduced from 647 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     7634    0.059    0.000    0.059    0.000 uuid.py:60(__hash__)
     6944    0.067    0.000    0.067    0.000 threading.py:609(currentThread)
     6944    0.127    0.000    0.194    0.000 threadlocal.py:39(_getCurrentThrea
dLocals)
     5714    0.044    0.000    0.044    0.000 item.py:2283(_loadItem)
     5648    0.085    0.000    0.244    0.000 threadlocal.py:21(__getattr__)
5589/5372    0.146    0.000    0.222    0.000 item.py:151(__setattr__)
     5410    0.072    0.000    0.072    0.000 item.py:1211(hasAttributeValue)
     4914    0.076    0.000    0.076    0.000 item.py:2326(_countAccess)
4750/4418    0.273    0.000    1.155    0.000 item.py:513(getAttributeValue)
     4680    0.130    0.000    0.333    0.000 xmlrepository.py:466(_getTxn)


         167531 function calls (164442 primitive calls) in 18.681 CPU seconds

   Ordered by: cumulative time
   List reduced from 647 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001   18.681   18.681 calendarcanvas.py:427(OnCreateItem
)
        1    0.000    0.000   16.300   16.300 repository.py:152(commit)
        1    0.007    0.007   16.300   16.300 xmlrepositoryview.py:194(commit)
       56    0.030    0.001   15.830    0.283 xmlrepositoryview.py:289(_saveItem
)
       56    0.007    0.000   12.919    0.231 xmlrepository.py:533(saveItem)
       56    0.003    0.000   11.719    0.209 xmlrepository.py:244(putDocument)
       56   11.707    0.209   11.707    0.209 dbxml.py:82(putDocument)
       56    0.004    0.000    2.855    0.051 item.py:2180(_saveItem)
       56    0.016    0.000    2.849    0.051 item.py:2235(_xmlItem)
1059/1013    0.067    0.000    2.230    0.002 kind.py:121(getAttribute)

This second profile is from step #5, a bit quicker response.

         48424 function calls (47748 primitive calls) in 4.689 CPU seconds

   Ordered by: internal time, call count
   List reduced from 479 to 50 due to restriction <50>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       24    2.280    0.095    2.280    0.095 dbxml.py:82(putDocument)
       74    0.908    0.012    0.918    0.012 dbcontainer.py:63(put)
1829/1751    0.102    0.000    0.231    0.000 item.py:513(getAttributeValue)
        1    0.087    0.087    0.087    0.087 xmlrepository.py:444(commitTransac
tion)
      806    0.077    0.000    0.077    0.000 sax.py:80(startElement)
2000/1825    0.051    0.000    0.118    0.000 item.py:151(__setattr__)
       28    0.042    0.001    0.049    0.002 dbxml.py:213(next)
     1255    0.034    0.000    0.043    0.000 linkedmap.py:80(_get)
      325    0.029    0.000    0.141    0.000 types.py:504(_fieldXML)
  201/199    0.029    0.000    0.272    0.001 itemhandler.py:556(xmlValue)
     1241    0.028    0.000    0.097    0.000 itemref.py:136(other)
  955/909    0.028    0.000    0.113    0.000 attribute.py:28(getAspect)
      185    0.028    0.000    0.076    0.000 dbcontainer.py:559(readName)
      418    0.027    0.000    0.345    0.001 kind.py:121(getAttribute)
     1856    0.027    0.000    0.027    0.000 item.py:2326(_countAccess)
     1331    0.026    0.000    0.036    0.000 itemref.py:43(getItem)
     2008    0.026    0.000    0.026    0.000 item.py:1211(hasAttributeValue)
     1241    0.025    0.000    0.034    0.000 itemref.py:54(getOther)
       24    0.025    0.001    0.570    0.024 values.py:160(_xmlValues)
     1075    0.024    0.000    0.223    0.000 linkedmap.py:322(__iter__)
   328/53    0.023    0.000    0.265    0.005 kind.py:306(isKindOf)
      610    0.022    0.000    0.059    0.000 itemref.py:918(_getRef)
1046/1032    0.022    0.000    0.146    0.000 item.py:141(__getattr__)
     1075    0.021    0.000    0.047    0.000 linkedmap.py:327(iterkeys)
      411    0.020    0.000    0.074    0.000 itemref.py:923(get)
      610    0.020    0.000    0.132    0.000 itemref.py:761(__getitem__)
      806    0.020    0.000    0.020    0.000 sax.py:96(endElement)
     2341    0.019    0.000    0.019    0.000 uuid.py:60(__hash__)
     1075    0.019    0.000    0.066    0.000 itemref.py:1187(iterkeys)
     2572    0.018    0.000    0.018    0.000 item.py:2283(_loadItem)
      373    0.018    0.000    0.029    0.000 repositoryview.py:517(__getitem__)

      411    0.016    0.000    0.126    0.000 item.py:857(getValue)
      430    0.016    0.000    0.144    0.000 kind.py:110(resolve)
      513    0.016    0.000    0.023    0.000 linkedmap.py:211(get)
     1271    0.016    0.000    0.016    0.000 item.py:1245(isNew)
      551    0.015    0.000    0.040    0.000 xmlrepository.py:466(_getTxn)
      531    0.014    0.000    0.014    0.000 sax.py:102(characters)
      340    0.013    0.000    0.048    0.000 itemhandler.py:531(typeHandler)
      683    0.013    0.000    0.020    0.000 threadlocal.py:39(_getCurrentThrea
dLocals)
      726    0.012    0.000    0.012    0.000 uuid.py:112(str64)
       65    0.012    0.000    0.176    0.003 types.py:490(typeXML)
      801    0.011    0.000    0.011    0.000 persistentcollections.py:89(_resto
reValue)
      610    0.011    0.000    0.031    0.000 linkedmap.py:105(__getitem__)
      439    0.010    0.000    0.067    0.000 item.py:1920(getItemChild)
      351    0.010    0.000    0.010    0.000 values.py:98(_getFlags)
      469    0.010    0.000    0.015    0.000 persistentcollections.py:360(iteri
tems)
      373    0.010    0.000    0.015    0.000 persistentcollections.py:348(get)
      617    0.010    0.000    0.028    0.000 threadlocal.py:21(__getattr__)
      191    0.009    0.000    0.021    0.000 dbcontainer.py:78(cursor)
       24    0.009    0.000    4.021    0.168 xmlrepositoryview.py:289(_saveItem
)


         48424 function calls (47748 primitive calls) in 4.689 CPU seconds

   Ordered by: call count
   List reduced from 479 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     2572    0.018    0.000    0.018    0.000 item.py:2283(_loadItem)
     2341    0.019    0.000    0.019    0.000 uuid.py:60(__hash__)
     2008    0.026    0.000    0.026    0.000 item.py:1211(hasAttributeValue)
2000/1825    0.051    0.000    0.118    0.000 item.py:151(__setattr__)
     1856    0.027    0.000    0.027    0.000 item.py:2326(_countAccess)
1829/1751    0.102    0.000    0.231    0.000 item.py:513(getAttributeValue)
     1331    0.026    0.000    0.036    0.000 itemref.py:43(getItem)
     1271    0.016    0.000    0.016    0.000 item.py:1245(isNew)
     1255    0.034    0.000    0.043    0.000 linkedmap.py:80(_get)
     1241    0.028    0.000    0.097    0.000 itemref.py:136(other)


         48424 function calls (47748 primitive calls) in 4.689 CPU seconds

   Ordered by: cumulative time
   List reduced from 479 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    4.689    4.689 calendarcanvas.py:427(OnCreateItem
)
        1    0.000    0.000    4.280    4.280 repository.py:152(commit)
        1    0.003    0.003    4.280    4.280 xmlrepositoryview.py:194(commit)
       24    0.009    0.000    4.021    0.168 xmlrepositoryview.py:289(_saveItem
)
       24    0.003    0.000    2.984    0.124 xmlrepository.py:533(saveItem)
       24    0.002    0.000    2.286    0.095 xmlrepository.py:244(putDocument)
       24    2.280    0.095    2.280    0.095 dbxml.py:82(putDocument)
       24    0.002    0.000    1.017    0.042 item.py:2180(_saveItem)
       24    0.007    0.000    1.015    0.042 item.py:2235(_xmlItem)
       74    0.908    0.012    0.918    0.012 dbcontainer.py:63(put)

-- KatieCappsParlante - 22 Sep 2004