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

Accessibility/Documentation/GNOME2/ATSPI2-Investigation/OrcaExtraProfiling (last edited 2011-07-21 18:14:01 by JoanmarieDiggs)