View Issue Details

IDProjectCategoryView StatusLast Update
0001585ardourbugspublic2009-08-31 20:03
Reporternmains Assigned To 
Status feedbackResolutionopen 
Summary0001585: fit_to_pixels is a big bottleneck in "zoom"
Descriptionrunning oprofile while zooming a large session (lots of regions on lots of tracks)
produced this set of files.
TagsNo tags attached.


2007-03-29 06:21


allcalls.out (284,355 bytes)

2007-03-29 06:22


gnomecanvas.out (11,287 bytes)

2007-03-29 06:23


glibmm.out (14,787 bytes)

2007-03-29 06:24


gtkmm.out (14,597 bytes)

2007-03-29 06:24


pangomm.out (455 bytes)

2007-03-29 06:32


libardour.out (19,540 bytes)

2007-03-29 06:35


libgtkmm2ext.out (27,039 bytes)


2007-03-29 06:56

developer   ~0003682

possible optimisations:

libgtkmm2ext.out reveals a lot of time spent in get_ink_pixel_size() which is called by reset_name_width () pretty much unconditionally during zoom in TimeAxisViewItem::reset_width_dependent_items ().

wrt regions:

get_ink_pixel_size() will always return the same thing as long as the name is shorter than the region. could this be cached?

get_ink_pixel_size() shouldn't be needed if the name is obscured by another region.

please add any other observations gleaned from this data.


2007-03-29 06:59

developer   ~0003683

glibmm.out first line. 50% in Glib::Mutex::lock()

2007-03-29 07:00


libpbd.out (24,066 bytes)


2007-03-29 14:54

developer   ~0003684

The Glibmm::lock call runtime is kind of "normal". If there were more ways to avoid locking in the code, ok... but that lib is always going to be dominated by lock time


2007-03-29 14:57

developer   ~0003685

yea, calling the pango layout module repeatedly is "bad". It should only be called when the name of the region changes or the clip region changes...

does all this stuff get called even when the region at hand is offscreen?


2007-03-29 15:16

developer   ~0003686

Just wanted to make clear that while oprofiling, you are profiling the whole system, and the percentages reported by opreport reflect that.

When you dig further and do it on a per library basis - you are profiling the total time spent in that module against the percentage of time per call.

So, if you are spending 20% of your time in libardour, and you profile libardour, the total time shown in calls there as reported by opreport -c will add up to 100% but really only account for 20% of the run time.

Amdahl's law always applies when profiling....

In the case of these oprofiles, I am additionally puzzled by the amount of time spent in "random" of all places. A lot of modern arches have a hardware rng... but what the heck is calling "random"? (not that it matters all that much, according to amdahl......


2007-03-29 15:23

developer   ~0003687

Last edited: 2007-03-29 15:24

Would love to see an oprofile with reset_name_width commented out. It would be my hope that calls to pango and many of the glib routines would completely disappear from the runtime, but there is no sureity in that.

2007-03-30 11:31


allcalls_no_reset.out (306,750 bytes)

2007-03-30 11:32


glibmm_no_reset.out (9,925 bytes)

2007-03-30 11:34


gtkmm_no_reset.out (17,207 bytes)

2007-03-30 11:35


gnomecanvas_no_reset.out (12,118 bytes)

2007-03-30 11:36


2007-03-30 11:38


libardour_no_reset.out (22,611 bytes)

2007-03-30 11:39


libpbd_no_reset.out (7,348 bytes)


2007-03-30 11:42

developer   ~0003688

ok i've uploaded the "no reset" series of results which used a "nuked reset_name_width" patch.


2007-03-30 11:43

developer   ~0003689

by the way, there is no pangomm_no_reset.out because there were no results :)


2007-03-31 03:39

developer   ~0003690

Just poking around, and had to vent.

>5549 12.5694 Glib::ValueBase::init(unsigned long)

Yes - boys and girls - Glib is spending 12.6% of the runtime in this module, making at least two function calls... to init an opaque type. As best as I can tell without glibmm compiled for debugging. - a very, small opaque type.

This is the code that that wraps:

void ValueBase::init(GType type)
  g_value_init(&gobject_, type);

>4631 10.4900 Glib::PropertyProxy_Base::set_property_(Glib::ValueBase const&)

I don't know what this does, I'm scared to find out.
>4621 10.4673 Glib::Value<double>::set(double)

A little template specialization here in Glib for common types would make some sense.

>4553 10.3133 Glib::Value<double>::value_type()

1707 3.8666 Glib::ValueBase::ValueBase()

Now, I do have a great deal of joy in actually seeing GLIBMM_INITIALIZE_STRUCT
cleverly use gcc's __builtin_memset - which is a nice inline for short fills.... but the fact that the constructor is wrapped in it's own little module trapped in a .cc file instead of a header bothers me.

// JOY in glibmm's "utilities.h"
#define GLIBMM_INITIALIZE_STRUCT(Var, Type) __builtin_memset(&(Var), 0, sizeof(Type))

// RAGE in glibmm's

But, you know, that ain't nothin compared to the destructor

>3108 7.0401 Glib::ValueBase::~ValueBase()


>3064 6.9404 .plt
>3009 6.8159 __i686.get_pc_thunk.bx

All this object oriented redirection joy leads to indirect memory references eating up another 13.5% of the runtime in this module.


2007-03-31 03:59

developer   ~0003691

but wait, there's more... gtkmm is also wrapping AND and OR operations in it's own, nice, tidy, little object oriented subclasses.

>758 12.9263 .plt

Ahhh... relocations... gotta love 'em.

>748 12.7558 Gtk::Widget::is_mapped() const

In gtk: This is a single structure member memory lookup and & against a set of flags in a #define.

In GTKMM - it's a whole falutin function call that hides in

bool Widget::is_drawable() const { return GTK_WIDGET_DRAWABLE(gobj()); }
                                           ^^^^ just an and

I incidentally got bothered at this point and rewrote the header file to inline these functions. A little bird tells me that inlining all this crap would actually generate smaller code as well as faster code. I haven't looked at it, but that is what the birdie says.....

>612 10.4366 Gtk::Widget::queue_draw()

In looking at the FastMeter code, perhaps queue_area_redraw (is that the right name?) just for the meter rectangle would be faster. Or just invalidate the rectangle. Still not clear to me if draw_pixbuf is the same as having the pixmap cached on the server in gtk. Please note that the high level of cynicism applied throughout the last two posts doesn't apply to queue_draw - coping with that one is kind of hard....

>540 9.2087 Gtk::Widget_Class::event_callback(_GtkWidget*, _GdkEvent*)

Ahh... this bit of code is 4 lines of typecasts and 4 actual lines of code. I'm so glad this is buried in a module of it's own and not a header file, so it can generate even more memory dereferences....

395 6.7360 __i686.get_pc_thunk.bx

Ahh... register pressure on all those relocations...

>371 6.3267 Glib::wrap(_GtkStyle*, bool)

Given all the places where this particular call is used, you'd think it would be highly optimized. I'm afraid to look.

>362 6.1733 Gtk::Widget::is_visible() const

Wow! lets' make a whole function call to do an AND operation! isn't that special?

I gave up at this point.

2007-04-02 05:06


allcalls_mtaht.out (267,605 bytes)


2007-04-02 05:07

developer   ~0003695

added allcalls_mtaht.out which is the current surfaces branch plus 'nuke pango' patch.

2007-04-02 05:36



2007-04-02 05:39

developer   ~0003696

uploaded allcalls_noreset_nocompiz.out which is an "equaliser" run for comparison between the surfaces branch + nuked pango (allcalls_mtaht.out) and plain "nuked pango"


2007-04-03 16:04

administrator   ~0003705

a recent commit contains a first pass attempt at optimizing out calls to get_ink_pixel_size() from reset_name_width()


2007-04-03 16:32

developer   ~0003706

also merged into surfaces branch. At least in there, calls to pango are GONE from the runtime.

Nice, paul.

2007-04-05 14:34



2007-04-05 14:39

developer   ~0003708

uploaded allcalls_trunk_plus_mtaht.out (no pango nuke).
trunk currently contains "sort-of cache time axis view item name widths and avoid pango-width-computation when unnecessary".


2007-04-05 14:54

developer   ~0003709

Darn it, how did pango get back in there?

2007-04-06 03:50



2007-04-06 03:52

developer   ~0003712

uploaded latest oprofile results since 1668 ("wash that pango right out of your hair").
see allcalls_trunk_clairol_plus_mtaht.out


2009-07-05 04:02

manager   ~0006312

Hmm is this still an issue with newer versions of Ardour (2.8 or probably better at this point is to examine 3.0)?


2009-08-31 20:03

manager   ~0006614

haven't really understood the metrics discussed here, but i can see severe performance problems at high zoom levels, where each action takes tens of seconds to be executed (on a single core athlon64 with 2.6 ghz)

Issue History

Date Modified Username Field Change
2007-03-29 06:21 nmains New Issue
2007-03-29 06:21 nmains File Added: allcalls.out
2007-03-29 06:22 nmains File Added: gnomecanvas.out
2007-03-29 06:23 nmains File Added: glibmm.out
2007-03-29 06:24 nmains File Added: gtkmm.out
2007-03-29 06:24 nmains File Added: pangomm.out
2007-03-29 06:32 nmains File Added: libardour.out
2007-03-29 06:35 nmains File Added: libgtkmm2ext.out
2007-03-29 06:56 nmains Note Added: 0003682
2007-03-29 06:59 nmains Note Added: 0003683
2007-03-29 07:00 nmains File Added: libpbd.out
2007-03-29 07:30 nmains Status new => feedback
2007-03-29 14:54 mtaht Note Added: 0003684
2007-03-29 14:57 mtaht Note Added: 0003685
2007-03-29 15:16 mtaht Note Added: 0003686
2007-03-29 15:23 mtaht Note Added: 0003687
2007-03-29 15:24 mtaht Note Edited: 0003687
2007-03-30 11:31 nmains File Added: allcalls_no_reset.out
2007-03-30 11:32 nmains File Added: glibmm_no_reset.out
2007-03-30 11:34 nmains File Added: gtkmm_no_reset.out
2007-03-30 11:35 nmains File Added: gnomecanvas_no_reset.out
2007-03-30 11:36 nmains File Added: libgtkmm2ext_no_reset.out
2007-03-30 11:38 nmains File Added: libardour_no_reset.out
2007-03-30 11:39 nmains File Added: libpbd_no_reset.out
2007-03-30 11:42 nmains Note Added: 0003688
2007-03-30 11:43 nmains Note Added: 0003689
2007-03-31 03:39 mtaht Note Added: 0003690
2007-03-31 03:59 mtaht Note Added: 0003691
2007-04-02 05:06 nmains File Added: allcalls_mtaht.out
2007-04-02 05:07 nmains Note Added: 0003695
2007-04-02 05:29 nmains File Added: allcalls_noresetr_nocompiz.out
2007-04-02 05:36 nmains File Deleted: allcalls_noresetr_nocompiz.out
2007-04-02 05:36 nmains File Added: allcalls_noreset_nocompiz.out
2007-04-02 05:39 nmains Note Added: 0003696
2007-04-03 16:04 paul Note Added: 0003705
2007-04-03 16:32 mtaht Note Added: 0003706
2007-04-05 14:34 nmains File Added: allcalls_trunk_plus_mtaht.out
2007-04-05 14:39 nmains Note Added: 0003708
2007-04-05 14:54 mtaht Note Added: 0003709
2007-04-06 03:50 nmains File Added: allcalls_trunk_clairol_plus_mtaht.out
2007-04-06 03:52 nmains Note Added: 0003712
2009-07-05 04:02 seablade Note Added: 0006312
2009-07-05 04:02 seablade Description Updated
2009-08-31 20:03 nettings Note Added: 0006614