View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0001585 | ardour | bugs | public | 2007-03-29 06:21 | 2009-08-31 20:03 |
| Reporter | nmains | Assigned To | |||
| Priority | normal | Severity | minor | Reproducibility | always |
| Status | feedback | Resolution | open | ||
| Summary | 0001585: fit_to_pixels is a big bottleneck in "zoom" | ||||
| Description | running oprofile while zooming a large session (lots of regions on lots of tracks) produced this set of files. | ||||
| Tags | No tags attached. | ||||
|
2007-03-29 06:21
|
|
|
2007-03-29 06:22
|
|
|
2007-03-29 06:23
|
|
|
2007-03-29 06:24
|
|
|
2007-03-29 06:24
|
|
|
2007-03-29 06:32
|
|
|
2007-03-29 06:35
|
|
|
|
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. |
|
|
glibmm.out first line. 50% in Glib::Mutex::lock() |
|
2007-03-29 07:00
|
|
|
|
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 |
|
|
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? |
|
|
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 libardour.so 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...... |
|
|
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
|
|
|
2007-03-30 11:32
|
|
|
2007-03-30 11:34
|
|
|
2007-03-30 11:35
|
|
|
2007-03-30 11:36
|
|
|
2007-03-30 11:38
|
|
|
2007-03-30 11:39
|
|
|
|
ok i've uploaded the "no reset" series of results which used a "nuked reset_name_width" patch. |
|
|
by the way, there is no pangomm_no_reset.out because there were no results :) |
|
|
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() Ditto. 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 value.cc ValueBase::ValueBase() { GLIBMM_INITIALIZE_STRUCT(gobject_, GValue); } But, you know, that ain't nothin compared to the destructor >3108 7.0401 Glib::ValueBase::~ValueBase() ValueBase::~ValueBase() { g_value_unset(&gobject_); } >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. |
|
|
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 widget.cc: 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.... [self] ------------------------------------------------------------------------------- 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
|
|
|
|
added allcalls_mtaht.out which is the current surfaces branch plus 'nuke pango' patch. |
|
2007-04-02 05:36
|
|
|
|
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" |
|
|
a recent commit contains a first pass attempt at optimizing out calls to get_ink_pixel_size() from reset_name_width() |
|
|
also merged into surfaces branch. At least in there, calls to pango are GONE from the runtime. Nice, paul. |
|
2007-04-05 14:34
|
|
|
|
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". |
|
|
Darn it, how did pango get back in there? |
|
2007-04-06 03:50
|
|
|
|
uploaded latest oprofile results since 1668 ("wash that pango right out of your hair"). see allcalls_trunk_clairol_plus_mtaht.out |
|
|
Hmm is this still an issue with newer versions of Ardour (2.8 or probably better at this point is to examine 3.0)? |
|
|
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) |
| 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 |
