Re: Gtk performance issues from a user's point of view

[Federico Mena Quintero <federico ximian com>]

On Thu, 2006-10-05 at 16:56 +0200, Adalbert Dawid wrote:

> I created some profiles which you can fetch from
> http://jagga.rinux.net/profiles/
> All of them were created on an up-to-date Ubuntu Edgy (GTK 2.10) with
> compositing turned off and debugging symbols installed for all relevant
> (AFAICT) packages.

Nice, thanks!  These are pretty useful.

> table_nautilus.profile.gz was generated by resizing a column of
> nautilus' list view (containing > 300 files) for about 10 seconds.

Interesting things about this one:

- The X server uses 30% of the time.  5.5% is fbSolidFillmmx().  7.9% is
"in kernel" - no idea what that means.  Some DMA or something?

- gtk_cell_renderer_text_render() is a big problem (24% of the time).
The problem is known: it causes the same text to be measured more than
once.  This should not be hard to fix; it just needs someone to take a
look.

- In Nautilus, fm_list_model_get_value() spends a good amount of time
(11.5%) re-fetching icons for the files.  It should do this only once
when it first finds the files, and then just re-use the icons until the
icon theme changes (or the file changes, of course).  You may want to
report this profile to nautilus-list.

I'd start by fixing GtkCellRendererText.  This would benefit
*everything* that uses a treeview, including my beloved file chooser ;)

Then, I'd fix the X server - easier said than done.  It's probably not
too important to fix FMListModel in Nautilus at this point, as one
doesn't resize columns in the file manager that often.

> table_evolution.profile.gz was created by resizing a column of
> evolution's list of mails (containing > 270 entries) for about 10
> seconds.

Note that Evolution uses ETable, not GtkTreeView, for its message list.
ETable is a custom list widget written for Evolution.

- A whopping 41.7% of the time goes in the X server.  14.26% in
fbComposite(), 6.7% in miTrapezoids(), 6.46% "in kernel".

- Amazingly, ethi_draw() ("draw the table headers") takes 22.26% of the
time, versus eti_draw() ("draw the contents of the table"), which is
only 19.44%.  Drawing the header buttons and their text takes longer
than drawing the actual contents of the table!

- For the headers, 15% is Cairo inside Clearlooks inside
gtk_paint_box().  This is pretty sad; it means that drawing buttons is
pretty slow.

- For the table contents, 13% is Pango inside ECellText.  This is not
too bad; it's about half the time that GtkTreeView takes to layout text.

As usual, fixing the X server is the way to go here.

[If your hard disk goes chug-chug-chug every time you resize a mail
header in Evolution, it's because Evo is stupid and writes the
configuration files on every mouse move while resizing.  It should only
write the configuration file when you finish dragging...]

> Additionally, I created four profiles for resizing (again ~10 seconds) a
> window containing a single, full sized {GTK, Qt} button with a {plain,
> gradient} decoration.

81% in the X server - enough said ;)

> I'm not sure if these profiles are useful for anyone, though...

They are!  They help pinpoint the problems.  Some of them are already
known (GtkCellRendererText is slow; X is slow), and some of them may
become hotspots in the future (FMListModel in Nautilus) once the more
important problems get solved.

> Some questions concerning sysprof:
> - What do the numbers in the "Self" and "Total" (resp. "Cumulative")
> columns mean exactly? 

If you have this function:

  void 
  foo (void)
  {
      int i;
      int sum;

      for (i = 0; i < 100000; i++)
          sum += i * i;

      bar (sum);
  }

and you have this profile:

   func		self	cumulative
   foo()        40%     50%
     bar()      10%     10%

Then it means this:

- 50% of the system's total time is spent in foo().

- 40% of the system's total time is spent in foo() itself, not its
children.  That is, 40% is the "for" loop - additions, multiplications,
and comparisons.

- bar() takes 10% of the system's time, and it has no child functions.

"Cumulative" is the time spent in a function and all the sub-functions
which it calls.  "Self" is the time in the function itself, without
counting its children.

> - What is a "Sample" in this context?

Sysprof is a statistical profiler, not an instrumenting one.

A statistical profiler stops your program N times per second; those are
the samples.  Each time it stops, it takes a stack trace and logs it.
Later, it looks at all the stack traces and counts how many times each
function appears.  It may miss functions that are very fast and executed
very seldom, if no samples get taken during their execution.

An instrumenting profiler actually installs timers and logging code in
the entry and exit points of functions.  This makes your program much
slower.  However, it lets you count how many times each function
executes.

> - Is there any way to get to know how many times a specific function was
> called and/or how long it took to proceed?

Not with sysprof, unfortunately.  You'd need something like gprof for
that.

  Federico