IMPORTANT: This article is being preserved for historical purposes and likely no longer reflects the state of AT-SPI over D-Bus.
Orca profiling
The pyatspi module was modified to record all calls and log them out to a file at the end of the logging process. The httpserver in Orca was used to enable/disable logging remotely while running.
The following use cases were looked at:
- Starting Orca on a clean Ubuntu desktop
- Starting the gedit application
- Closing the gedit application
- Typing text into a terminal window
- Moving around the calculator application using TAB
The cases are somewhat unscientific in that they have been performed by hand, and are therefore unrepeatable.A full run of the orca test harness was also profiled, and this should be repeatable. The python logging code can be found here and the httpserver changes here.
The graphs show the number of calls made per 100ms, with time across the bottom axis.
Starting Orca
Frequency of method calls:
- getRole - 36.8%
- _get_parent - 24.7%
- registerGlobalEventListener - 6.7%
- getState - 5.9%
- notifyEvent - 5.4%
- getChildAtIndex - 4.9%
- _get_childCount - 3.8%
- getRelationSet - 3.6%
- getApplication - 3.1%
- getDesktop - 1.8%
- getRoleName - 1.6%
- getAttributes - 1.0%
- _get_toolkitName - 0.7%
Highest calls per 100ms = 321
TAB between UI elements
Frequency of method calls:
- getRole - 47.6%
- _get_parent - 21.7%
- getChildAtIndex - 19.2%
- getRelationSet - 2.9%
- getState - 2.4%
- _get_childCount - 1.6%
- getRoleName - 1.4%
- notifyEvent - 1.2%
- getApplication - 1.0%
- getAttributes - 0.9%
- getDesktop - 0.1%
Highest calls per 100ms = 609
Starting Gedit
Frequency of method calls:
- getRole - 47.5%
- _get_parent - 16.0%
- notifyEvent - 8.9%
- getState - 7.8%
- getRelationSet - 4.3%
- getApplication - 3.9%
- getChildAtIndex - 2.9%
- getDesktop - 2.8%
- _get_childCount - 1.7%
- getAttributes - 1.7%
- getRoleName - 1.5%
- _get_caretOffset - 0.6%
- _get_characterCount - 0.4%
Highest calls per 100ms = 115, 127, 176, 247, 267, 325
Closing Gedit
Frequency of method calls:
- notifyEvent - 40.5%
- getDesktop - 22.1%
- getRole - 15.9%
- getChildAtIndex - 7.2%
- _get_parent - 4.8%
- getState - 3.6%
- getRelationSet - 1.7%
- getApplication - 1.5%
- _get_childCount - 0.9%
- getRoleName - 0.7%
- getAttributes - 0.5%
- _get_caretOffset - 0.4%
- _get_characterCount - 0.2%
Highest calls per 100ms = 70, 70, 70, 70, 77, 101, 127, 317
Typing in terminal
Frequency of method calls:
- getRole - 55.6%
- _get_parent - 16.7%
- getRelationSet - 4.8%
- _get_caretOffset - 4.3%
- getChildAtIndex - 3.5%
- _get_characterCount - 3.1%
- _get_childCount - 3.1%
- getRoleName - 2.6%
- getAttributes - 2.2%
- getState - 2.0%
- notifyEvent - 1.0%
- getApplication - 1.0%
Highest calls per 100ms = 216, 218, 233, 250, 252, 259, 298, 309, 324
Orca test harness
As a more repeatable test the AT-SPI calls made while running the Orca test harness were also looked at. The Orca test harness was run through all tests using runall.sh script. Records of all AT-SPI calls made were analyzed.
Frequency of method calls:
- getRole - 47.5%
- _get_parent - 18.4%
- getState - 6.8%
- getRelationSet - 4.6%
- getRoleName - 4.3%
- notifyEvent - 3.9%
- getApplication - 3.5%
- getChildAtIndex - 2.6%
- getAttributes - 2.4%
- _get_caretOffset - 1.7%
- getDesktop - 1.5%
- _get_childCount - 1.4%
- _get_characterCount - 1.2%
- registerGlobalEventListener - 0.1%
- deregisterGlobalEventListener - 0.1%
- _get_toolkitName - 0.0%
- _get_startIndex - 0.0%
- _get_endIndex - 0.0%
Higest calls per 100ms = 699