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

["Adalbert Dawid" <dawid rinux net>]

Am Fri, 06 Oct 2006 11:26:48 -0500 schrieb Federico Mena Quintero:

> 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.
> 
:-) Glad to hear that!

>> 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.
> 
Done: http://mail.gnome.org/archives/nautilus-list/2006-October/msg00018.html

> 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.

OK, thanks for the detailed explanations!

> 
>   Federico

-- 
Greetings,
Adalbert Dawid