Hi all,
Over the past year, or maybe even longer, I've been annoyed at how long it takes for Inkscape to start. Admittedly, I get easily annoyed because it takes only about 10 seconds for the main window to be drawn, but still.... After that it takes another 10 to 15 seconds before the CPU gets idle again, but during that second period Inkscape can already be used.
On launchpad I've seen reports that this could be related to the number of fonts installed, which could indeed be part of the problem. But I also noticed this across many systems, even when not that many fonts were installed. So I figured that the only way to find out was to do some profiling. I've attached only a part of the profiling output below (If you want all of it then I'll gladly send you the 18 MB file). Roughly the first 10 seconds have been profiled, because I immediately quit Inkscape as soon as the main window was drawn. (Actually the first phase takes a lot longer than 10 seconds when profiling; those 10 seconds have been measured with all debugging and profiling flags disabled)
What I found out was that it is prerender_icon() that causes the biggest part of the delay during those first 10 seconds. Maybe this is a public secret, but I just wanted to share this with you. I have no intention currently of improving this, but this at least allows us to respond accurately to some bug reports.
Regards,
Diederik
Flat profile:
Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls ms/call ms/call name 13.69 0.72 0.72 356031 0.00 0.01 nr_arena_item_invoke_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) 6.65 1.07 0.35 435568 0.00 0.00 Inkscape::Preferences::_getNode(Glib::ustring const&, bool) 5.51 1.36 0.29 28329840 0.00 0.00 Inkscape::XML::SimpleNode::attribute(char const*) const 4.85 1.62 0.26 57980026 0.00 0.00 Inkscape::Util::List<Inkscape::XML::AttributeRecord const>::operator->() const 4.18 1.84 0.22 28131371 0.00 0.00 _ZNK8Inkscape4Util10ptr_sharedIcEcvPKT_IcEEv 3.80 2.04 0.20 26795143 0.00 0.00 Inkscape::XML::SimpleNode::next() 3.42 2.22 0.18 32836208 0.00 0.00 Geom::Matrix::operator[](unsigned int) const 2.28 2.34 0.12 1236181 0.00 0.00 nr_object_check_instance_type(void const*, unsigned int) 2.28 2.46 0.12 797442 0.00 0.00 Geom::operator*(Geom::Matrix const&, Geom::Matrix const&) 1.81 2.55 0.10 30331635 0.00 0.00 Inkscape::Util::List<Inkscape::XML::AttributeRecord const>::operator bool() const 1.81 2.65 0.10 virtual thunk to Inkscape::XML::SimpleNode::attribute(char const*) const 1.71 2.74 0.09 1898740 0.00 0.00 Geom::operator*(Geom::Point const&, Geom::Matrix const&) 1.52 2.82 0.08 1661332 0.00 0.00 Geom::Bezier::at1() const 1.52 2.90 0.08 203312 0.00 0.01 nr_arena_shape_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) 1.24 2.96 0.07 9319609 0.00 0.00 Geom::Point::operator[](Geom::Dim2) const 0.95 3.01 0.05 813223 0.00 0.00 boost::shared_ptr<Geom::Curve const>::operator*() const 0.95 3.06 0.05 152487 0.00 0.00 nr_arena_group_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) 0.76 3.10 0.04 2750545 0.00 0.00 std::vector<Shape::dg_arete, std::allocatorShape::dg_arete
::operator[](unsigned long) const
0.76 3.14 0.04 2036510 0.00 0.00 cr_utils_read_char_from_utf8_buf 0.76 3.18 0.04 1558360 0.00 0.00 Geom::Matrix::operator=(Geom::Matrix const&) 0.76 3.22 0.04 1165706 0.00 0.00 NRArenaShape::Paint::type() const
% the percentage of the total running time of the time program used by this function.
cumulative a running sum of the number of seconds accounted seconds for by this function and those listed above it.
self the number of seconds accounted for by this seconds function alone. This is the major sort for this listing.
calls the number of times this function was invoked, if this function is profiled, else blank.
self the average number of milliseconds spent in this ms/call function per call, if this function is profiled, else blank.
total the average number of milliseconds spent in this ms/call function and its descendents per call, if this function is profiled, else blank.
name the name of the function. This is the minor sort for this listing. The index shows the location of the function in the gprof listing. If the index is in parenthesis it shows where it would appear in the gprof listing if it were to be printed.
Call graph (explanation follows)
granularity: each sample hit covers 2 byte(s) for 0.19% of 5.26 seconds
index % time self children called name 0.00 0.27 6/102 Inkscape::queueIconPrerender(Glib::ustring const&, Inkscape::IconSize) [33] 0.00 1.18 26/102 icon_prerender_task(void*) [15] 0.00 3.19 70/102 imageMapNamedCB(_GtkWidget*, void*) [5] [1] 88.3 0.00 4.64 102 prerender_icon(char const*, GtkIconSize, unsigned int) [1] 0.00 4.64 87/87 load_svg_pixels(char const*, unsigned int, unsigned int) [2] 0.00 0.00 182/186 std::set<Glib::ustring, std::lessGlib::ustring, std::allocatorGlib::ustring >::find(Glib::ustring const&) [545] 0.00 0.00 78/82 std::set<Glib::ustring, std::lessGlib::ustring, std::allocatorGlib::ustring >::insert(Glib::ustring const&) [640] 0.00 0.00 87/87 std::map<Glib::ustring, _GdkPixbuf*, std::lessGlib::ustring, std::allocator<std::pair<Glib::ustring const, _GdkPixbuf*> >
::operator[](Glib::ustring const&) [1199]
0.00 0.00 102/102 get_cached_pixbuf(Glib::ustring const&) [1229] 0.00 0.00 87/87 addToIconSet(_GdkPixbuf*, char const*, GtkIconSize, unsigned int) [1466] 0.00 0.00 1/663464 Inkscape::Preferences::get() <cycle 1> [340] 0.00 0.00 1/663464 Inkscape::Preferences::getBool(Glib::ustring const&, bool) <cycle 1> [271] 0.00 0.00 182/186 std::set<Glib::ustring, std::lessGlib::ustring, std::allocatorGlib::ustring >::end() const [6073] 0.00 0.00 102/102 icon_cache_key(char const*, unsigned int) [6298] 0.00 0.00 95/99 std::_Rb_tree_const_iteratorGlib::ustring::operator!=(std::_Rb_tree_const_iteratorGlib::ustring const&) const [6311] 0.00 0.00 87/87 std::_Rb_tree_const_iteratorGlib::ustring::operator==(std::_Rb_tree_const_iteratorGlib::ustring const&) const [6385] ----------------------------------------------- 0.00 4.64 87/87 prerender_icon(char const*, GtkIconSize, unsigned int) [1] [2] 88.2 0.00 4.64 87 load_svg_pixels(char const*, unsigned int, unsigned int) [2] 0.00 4.51 87/87 sp_icon_doc_icon [3] 0.02 0.11 1/2 sp_item_invoke_show(SPItem*, NRArena*, unsigned int, unsigned int) <cycle 5> [46] 0.00 0.01 1/13 sp_document_ensure_up_to_date(SPDocument*) [59] 0.00 0.00 1/2 sp_document_new(char const*, unsigned int, bool) [695] 0.00 0.00 174/174 std::map<Glib::ustring, svg_doc_cache_t*, std::lessGlib::ustring, std::allocator<std::pair<Glib::ustring const, svg_doc_cache_t*> >
::find(Glib::ustring const&) [1328]
0.00 0.00 1/1 std::map<Glib::ustring, svg_doc_cache_t*, std::lessGlib::ustring, std::allocator<std::pair<Glib::ustring const, svg_doc_cache_t*> >
::operator[](Glib::ustring const&) [1797]
0.00 0.00 1/2 NRArena::create() [1862] 0.00 0.00 261/276 std::list<char*, std::allocator<char*> >::end() [5914] 0.00 0.00 261/267 std::_List_iterator<char*>::operator!=(std::_List_iterator<char*> const&) const [5930] 0.00 0.00 174/183 std::_List_iterator<char*>::operator*() const [6076] 0.00 0.00 174/175 std::map<Glib::ustring, svg_doc_cache_t*, std::lessGlib::ustring, std::allocator<std::pair<Glib::ustring const, svg_doc_cache_t*> >
::end() [6084]
0.00 0.00 174/174 std::_Rb_tree_iterator<std::pair<Glib::ustring const, svg_doc_cache_t*>
::operator!=(std::_Rb_tree_iterator<std::pair<Glib::ustring const,
svg_doc_cache_t*> > const&) const [6087] 0.00 0.00 174/178 std::_List_iterator<char*>::operator++() [6080] 0.00 0.00 88/256 Inkscape::IO::file_test(char const*, GFileTest) [5942] 0.00 0.00 87/87 icons_svg_paths() [6378] 0.00 0.00 87/99 std::list<char*, std::allocator<char*> >::begin() [6313] 0.00 0.00 86/86 std::_Rb_tree_iterator<std::pair<Glib::ustring const, svg_doc_cache_t*>
::operator->() const [6395]
0.00 0.00 1/8 sp_item_display_key_new(unsigned int) [7822] 0.00 0.00 1/95963 sp_item_get_type() [2923] ----------------------------------------------- 0.00 4.51 87/87 load_svg_pixels(char const*, unsigned int, unsigned int) [2] [3] 85.7 0.00 4.51 87 sp_icon_doc_icon [3] 0.84 3.29 135/136 nr_arena_item_invoke_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [6] 0.00 0.37 87/87 nr_arena_item_invoke_render(_cairo*, NRArenaItem*, NRRectL const*, NRPixBlock*, unsigned int) <cycle 11> [26] 0.00 0.00 87/4399 SPItem::getBounds(Geom::Matrix const&, SPItem::BBoxType, unsigned int) const [84] 0.00 0.00 135/3802 nr_arena_item_set_transform(NRArenaItem*, Geom::Matrix const&) [210] 0.00 0.00 174/663464 Inkscape::Preferences::get() <cycle 1> [340] 0.00 0.00 174/663464 Inkscape::Preferences::getBool(Glib::ustring const&, bool) <cycle 1> [271] 0.00 0.00 87/89 sp_item_i2doc_affine(SPItem const*) [1110] 0.00 0.00 135/142 Geom::Scale::operator Geom::Matrix() const [1396] 0.00 0.00 540/225255 boost::optional<Geom::D2Geom::Interval >::operator->() [538] 0.00 0.00 87/684872 Geom::OptRect::~OptRect() [113] 0.00 0.00 87/428739 boost::optional<Geom::D2Geom::Interval >::operator bool (boost::optional_detail::optional_base<Geom::D2Geom::Interval >::*)() const() const [382] 0.00 0.00 270/9489 Geom::D2Geom::Interval::min() const [1164] 0.00 0.00 270/9505 Geom::D2Geom::Interval::max() const [1163] 0.00 0.00 135/1010 Geom::Scale::Scale(double, double) [1517] 0.00 0.00 540/1789678 Geom::Point::operator[](Geom::Dim2) [2831] 0.00 0.00 261/95963 sp_item_get_type() [2923] 0.00 0.00 135/8015 Geom::Matrix::setIdentity() [3556] 0.00 0.00 87/5269 SPDocument::getObjectById(char const*) [3796] 0.00 0.00 87/712709 NRGC::NRGC(NRGC const*) [2849] 0.00 0.00 87/103582 int const& std::max<int>(int const&, int const&) [2919] 0.00 0.00 87/453 nr_pixblock_setup_extern(NRPixBlock*, NR_PIXBLOCK_MODE, int, int, int, int, unsigned char*, int, bool, bool) [5696] 0.00 0.00 87/1997 nr_pixblock_release(NRPixBlock*) [4561] ----------------------------------------------- [4] 79.2 0.85 3.31 136+711791 <cycle 10 as a whole> [4] 0.72 1.95 356031+291 nr_arena_item_invoke_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [6] 0.08 1.21 203312 nr_arena_shape_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [14] 0.05 0.15 152487 nr_arena_group_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [40] 0.00 0.00 97 nr_arena_glyphs_group_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [1516] ----------------------------------------------- <spontaneous> [5] 60.6 0.00 3.19 imageMapNamedCB(_GtkWidget*, void*) [5] 0.00 3.19 70/102 prerender_icon(char const*, GtkIconSize, unsigned int) [1] 0.00 0.00 70/103 sp_icon_get_phys_size(int) [1462] 0.00 0.00 10554/10554 __gnu_cxx::__normal_iterator<preRenderItem*, std::vector<preRenderItem, std::allocator<preRenderItem> > >::operator->() const [3445] 0.00 0.00 10458/10778 Glib::operator==(Glib::ustring const&, char const*) [3438] 0.00 0.00 10458/10659 std::vector<preRenderItem, std::allocator<preRenderItem> >::end() [3442] 0.00 0.00 10458/10554 bool __gnu_cxx::operator!=<preRenderItem*, std::vector<preRenderItem, std::allocator<preRenderItem> >
(__gnu_cxx::__normal_iterator<preRenderItem*,
std::vector<preRenderItem, std::allocator<preRenderItem> > > const&, __gnu_cxx::__normal_iterator<preRenderItem*, std::vector<preRenderItem, std::allocator<preRenderItem> > > const&) [3444] 0.00 0.00 10388/10388 __gnu_cxx::__normal_iterator<preRenderItem*, std::vector<preRenderItem, std::allocator<preRenderItem> > >::operator++() [3452] 0.00 0.00 70/132 std::vector<preRenderItem, std::allocator<preRenderItem> >::begin() [6218] 0.00 0.00 70/96 std::vector<preRenderItem, std::allocator<preRenderItem>
::erase(__gnu_cxx::__normal_iterator<preRenderItem*,
std::vector<preRenderItem, std::allocator<preRenderItem> > >) [6348] ----------------------------------------------- 291 nr_arena_item_invoke_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [6] 291 nr_arena_shape_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [14] 355604 nr_arena_group_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [40] 0.01 0.02 1/136 sp_canvas_arena_update(SPCanvasItem*, Geom::Matrix const&, unsigned int) [122] 0.84 3.29 135/136 sp_icon_doc_icon [3] [6] 50.8 0.72 1.95 356031+291 nr_arena_item_invoke_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [6] 0.00 1.79 203797/215263 nr_arena_item_request_render(NRArenaItem*) [7] 0.07 0.00 712606/1236181 nr_object_check_instance_type(void const*, unsigned int) [53] 0.03 0.03 178043/797442 Geom::operator*(Geom::Matrix const&, Geom::Matrix const&) [35] 0.01 0.00 534327/1558360 Geom::Matrix::operator=(Geom::Matrix const&) [103] 0.00 0.01 356284/356284 NRGC::operator=(NRGC const&) [437] 0.01 0.00 356284/521878 nr_arena_group_get_type() [379] 0.00 0.00 97/97 nr_arena_image_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) [689] 0.00 0.00 388/388 nr_arena_glyphs_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) [744] 0.00 0.00 291/30393 nr_rect_l_intersect(NRRectL*, NRRectL const*, NRRectL const*) [393] 0.00 0.00 356322/712709 NRGC::NRGC(NRGC const*) [2849] 0.00 0.00 356322/863943 nr_arena_item_get_type() [2845] 203312 nr_arena_shape_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [14] 152390 nr_arena_group_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [40] 97 nr_arena_glyphs_group_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [1516] 291 nr_arena_item_invoke_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [6] ----------------------------------------------- 0.00 0.00 2/215263 nr_arena_item_unparent(NRArenaItem*) [1319] 0.00 0.00 3/215263 nr_arena_item_set_clip(NRArenaItem*, NRArenaItem*) [1253] 0.00 0.00 4/215263 nr_arena_glyphs_set_path(NRArenaGlyphs*, SPCurve*, unsigned int, font_instance*, int, Geom::Matrix const*) [1214] 0.00 0.00 4/215263 nr_arena_glyphs_group_add_component(NRArenaGlyphsGroup*, font_instance*, int, Geom::Matrix const&) [1092] 0.00 0.00 97/215263 nr_arena_image_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) [689] 0.00 0.02 1932/215263 nr_arena_item_set_transform(NRArenaItem*, Geom::Matrix const*) [212] 0.00 0.02 2096/215263 nr_arena_shape_set_path(NRArenaShape*, SPCurve*, bool) [166] 0.00 0.03 3664/215263 nr_arena_item_set_opacity(NRArenaItem*, double) [116] 0.00 0.03 3664/215263 nr_arena_item_set_visible(NRArenaItem*, unsigned int) [117] 0.00 1.79 203797/215263 nr_arena_item_invoke_update(NRArenaItem*, NRRectL*, NRGC*, unsigned int, unsigned int) <cycle 10> [6] [7] 35.9 0.00 1.89 215263 nr_arena_item_request_render(NRArenaItem*) [7] 0.02 1.85 215263/215263 nr_arena_request_render_rect(NRArena*, NRRectL*) [9] 0.02 0.00 215263/1236181 nr_object_check_instance_type(void const*, unsigned int) [53] 0.00 0.00 215263/863943 nr_arena_item_get_type() [2845] ----------------------------------------------- [8] 35.7 0.08 1.80 663464+1538951 <cycle 1 as a whole> [8] 0.01 1.45 431095 Inkscape::Preferences::getInt(Glib::ustring const&, int) <cycle 1> [12] 0.00 0.14 2482 sp_style_merge_from_style_string(SPStyle*, char const*) <cycle 1> [49] 0.01 0.05 25012 sp_path_set(SPObject*, unsigned int, char const*) <cycle 1> [80] 0.01 0.04 459+28821 sp_repr_svg_read_node(Inkscape::XML::Document*, _xmlNode*, char const*, _GHashTable*) <cycle 1> [85] 0.00 0.03 35384+37576 Inkscape::XML::CompositeNodeObserver::notifyAttributeChanged(Inkscape::XML::Node&, unsigned int, Inkscape::Util::ptr_shared<char>, Inkscape::Util::ptr_shared<char>) <cycle 1> [125] 0.01 0.01 36965 Inkscape::XML::SimpleNode::setAttribute(char const*, char const*, bool) <cycle 1> [180] 0.00 0.02 2272 sigc::internal::signal_emit2<void, SPObject*, SPObject*, sigc::nil>::emit(sigc::internal::signal_impl*, SPObject* const&, SPObject* const&) <cycle 1> [230] 0.01 0.00 81742 sp_object_read_attr(SPObject*, char const*) <cycle 1> [260] 0.00 0.01 3622 Inkscape::Preferences::getBool(Glib::ustring const&, bool) <cycle 1> [271] 0.00 0.01 1739 sp_path_update_patheffect(SPLPEItem*, bool) <cycle 1> [297] 0.00 0.01 135 sp_svg_write_path(std::vector<Geom::Path, std::allocatorGeom::Path > const&) <cycle 1> [303] 0.01 0.00 650246 Inkscape::Preferences::get() <cycle 1> [340] 0.01 0.00 20173 sp_style_merge_style_from_decl(SPStyle*, _CRDeclaration const*) <cycle 1> [348] 0.01 0.00 5361 sp_arc_set(SPObject*, unsigned int, char const*) <cycle 1> [349] 0.00 0.01 20+518 Inkscape::XML::SimpleNode::mergeFrom(Inkscape::XML::Node const*, char const*) <cycle 1> [474] 0.00 0.00 3666 sp_style_read(SPStyle*, SPObject*, Inkscape::XML::Node*) <cycle 1> [526] 0.00 0.00 130 sp_genericellipse_update_patheffect(SPLPEItem*, bool) <cycle 1> [532] 0.00 0.00 4330 sp_object_invoke_build(SPObject*, SPDocument*, Inkscape::XML::Node*, unsigned int) <cycle 1> [569] 0.00 0.00 2270 Inkscape::URIReference::attach(Inkscape::URI const&) <cycle 1> [593] 0.00 0.00 11780 Inkscape::URIReference::_setObject(SPObject*) <cycle 1> [594] 0.00 0.00 457 sp_repr_do_read(_xmlDoc*, char const*) <cycle 1> [662] 0.00 0.00 47873 sp_item_set(SPObject*, unsigned int, char const*) <cycle 1> [674] 0.00 0.00 73 sigc::internal::signal_emit1<void, SPObject*, sigc::nil>::emit(sigc::internal::signal_impl*, SPObject* const&) <cycle 1> [800] 0.00 0.00 4330 sp_object_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [901] 0.00 0.00 3976 SPGradientImpl::setGradientAttr(SPObject*, unsigned int, char const*) <cycle 1> [925] 0.00 0.00 12196 sp_style_merge_ipaint(SPStyle*, SPIPaint*, SPIPaint const*) <cycle 1> [993] 0.00 0.00 4 LivePathEffectObject::livepatheffect_set(SPObject*, unsigned int, char const*) <cycle 1> [1003] 0.00 0.00 965 sp_use_href_changed(SPObject*, SPObject*, SPUse*) <cycle 1> [1089] 0.00 0.00 6 sp_string_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [1113] 0.00 0.00 2 sp_star_update_patheffect(SPLPEItem*, bool) <cycle 1> [1148] 0.00 0.00 861 sp_style_set_ipaint_to_uri(SPStyle*, SPIPaint*, Inkscape::URI const*, SPDocument*) <cycle 1> [1170] 0.00 0.00 962 sp_path_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [1243] 0.00 0.00 497 SPGradientImpl::build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [1245] 0.00 0.00 882 sp_stop_set(SPObject*, unsigned int, char const*) <cycle 1> [1338] 0.00 0.00 58799 SPIPaint::clear() <cycle 1> [1543] 0.00 0.00 245 Inkscape::XML::(anonymous namespace)::VectorNodeObserver::notifyAttributeChanged(Inkscape::XML::Node&, unsigned int, Inkscape::Util::ptr_shared<char>, Inkscape::Util::ptr_shared<char>) <cycle 1> [1545] 0.00 0.00 962 sp_path_set_original_curve(SPPath*, SPCurve*, unsigned int, bool) <cycle 1> [1610] 0.00 0.00 135 Inkscape::SVG::PathString::PathString() <cycle 1> [1635] 0.00 0.00 252 SPStop::readStopColor(Glib::ustring const&, unsigned int) <cycle 1> [1664] 0.00 0.00 2+27 (anonymous namespace)::strip_ids_recursively(Inkscape::XML::Node*) <cycle 1> [1681] 0.00 0.00 1 LivePathEffectObject::livepatheffect_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [1686] 0.00 0.00 2 sp_namedview_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [1692] 0.00 0.00 10 sp_guide_set(SPObject*, unsigned int, char const*) <cycle 1> [1714] 0.00 0.00 2 Inkscape::Preferences::_load() <cycle 1> [1734] 0.00 0.00 2 sp_root_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [1740] 0.00 0.00 20 sp_image_set(SPObject*, unsigned int, char const*) <cycle 1> [1756] 0.00 0.00 2 Inkscape::loadImpl(std::string const&, Glib::ustring&) <cycle 1> [1758] 0.00 0.00 9000 sp_group_set(SPObject*, unsigned int, char const*) <cycle 1> [1760] 0.00 0.00 8267 sp_style_clear(SPStyle*) <cycle 1> [1771] 0.00 0.00 23 sp_marker_set(SPObject*, unsigned int, char const*) <cycle 1> [1776] 0.00 0.00 3 sp_clippath_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [1778] 0.00 0.00 2 sp_metadata_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [1800] 0.00 0.00 1 sp_image_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [1807] 0.00 0.00 1 Inkscape::DocumentSubset::Relations::remove(SPObject*, bool) <cycle 1> [1808] 0.00 0.00 281 sp_style_unref(SPStyle*) <cycle 1> [1847] 0.00 0.00 431095 Inkscape::Preferences::Entry::getInt(int) const <cycle 1> [2869] 0.00 0.00 81741 sp_object_set(SPObject*, unsigned int, char const*) <cycle 1> [2938] 0.00 0.00 37957 sp_lpe_item_set(SPObject*, unsigned int, char const*) <cycle 1> [3015] 0.00 0.00 29557 sp_shape_set(SPObject*, unsigned int, char const*) <cycle 1> [3073] 0.00 0.00 20560 sp_object_private_set(SPObject*, unsigned int, char const*) <cycle 1> [3174] 0.00 0.00 2482+17691 sp_style_merge_from_decl_list(SPStyle*, _CRDeclaration const*) <cycle 1> [4360] 0.00 0.00 20173 sp_style_merge_property(SPStyle*, int, char const*) <cycle 1> [3178] 0.00 0.00 17680 sp_rect_set(SPObject*, unsigned int, char const*) <cycle 1> [3222] 0.00 0.00 17406 sp_use_set(SPObject*, unsigned int, char const*) <cycle 1> [3224] 0.00 0.00 9381 Inkscape::URIReference::detach() <cycle 1> [3498] 0.00 0.00 7832 sp_style_merge_from_parent(SPStyle*, SPStyle const*) <cycle 1> [3567] 0.00 0.00 5772 SPConnEndPair::setAttr(unsigned int, char const*) <cycle 1> [3748] 0.00 0.00 5748 sp_lineargradient_set(SPObject*, unsigned int, char const*) <cycle 1> [3752] 0.00 0.00 4710 SPIPaint::read(char const*, SPStyle&, SPDocument*) <cycle 1> [3864] 0.00 0.00 4601 sp_style_new(SPDocument*) <cycle 1> [3890] 0.00 0.00 3664 sp_style_read_from_object(SPStyle*, SPObject*) <cycle 1> [4083] 0.00 0.00 3664 sp_item_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [4084] 0.00 0.00 3639 Inkscape::Preferences::Entry::getBool(bool) const <cycle 1> [4113] 0.00 0.00 2907 SPDocument::bindObjectToId(char const*, SPObject*) <cycle 1> [4277] 0.00 0.00 2694 sp_lpe_item_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [4332] 0.00 0.00 2272 sigc::signal2<void, SPObject*, SPObject*, sigc::nil>::emit(SPObject* const&, SPObject* const&) const <cycle 1> [4403] 0.00 0.00 2094 sp_shape_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [4547] 0.00 0.00 1924 SPConnEnd::setAttacherHref(char const*, SPPath*) <cycle 1> [4625] 0.00 0.00 1518 sp_lpe_item_update_patheffect(SPLPEItem*, bool, bool) <cycle 1> [4797] 0.00 0.00 967 sp_use_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [5025] 0.00 0.00 965 sigc::internal::slot_call2<sigc::bind_functor<-1, sigc::pointer_functor3<SPObject*, SPObject*, SPUse*, void>, SPUse*, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil>, void, SPObject*, SPObject*>::call_it(sigc::internal::slot_rep*, SPObject* const&, SPObject* const&) <cycle 1> [5081] 0.00 0.00 965 sigc::bind_functor<-1, sigc::pointer_functor3<SPObject*, SPObject*, SPUse*, void>, SPUse*, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil>::deduce_result_type<SPObject* const&, SPObject* const&, void, void, void, void, void>::type sigc::bind_functor<-1, sigc::pointer_functor3<SPObject*, SPObject*, SPUse*, void>, SPUse*, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil>::operator()<SPObject* const&, SPObject* const&>(SPObject* const&, SPObject* const&) <cycle 1> [5056] 0.00 0.00 965 sigc::adaptor_functor<sigc::pointer_functor3<SPObject*, SPObject*, SPUse*, void> >::deduce_result_type<SPObject* const&, SPObject* const&, SPUse*&, void, void, void, void>::type sigc::adaptor_functor<sigc::pointer_functor3<SPObject*, SPObject*, SPUse*, void> >::operator()<SPObject* const&, SPObject* const&, SPUse*&>(SPObject* const&, SPObject* const&, SPUse*&) const <cycle 1> [5092] 0.00 0.00 965 sigc::pointer_functor3<SPObject*, SPObject*, SPUse*, void>::operator()(SPObject* const&, SPObject* const&, SPUse* const&) const <cycle 1> [5093] 0.00 0.00 962 sp_conn_end_pair_build(SPObject*) <cycle 1> [5101] 0.00 0.00 884 sp_rect_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [5189] 0.00 0.00 857 sp_style_set_ipaint_to_uri_string(SPStyle*, SPIPaint*, char const*) <cycle 1> [5236] 0.00 0.00 555+144 sp_group_update_patheffect(SPLPEItem*, bool) <cycle 1> [5495] 0.00 0.00 600 sp_group_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [5470] 0.00 0.00 479 sp_lineargradient_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [5608] 0.00 0.00 339 sp_repr_read_mem(char const*, int, char const*) <cycle 1> [5848] 0.00 0.00 245 sp_object_repr_attr_changed(Inkscape::XML::Node*, char const*, char const*, char const*, bool, void*) <cycle 1> [5982] 0.00 0.00 244 sp_arc_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [5983] 0.00 0.00 234 sp_radialgradient_set(SPObject*, unsigned int, char const*) <cycle 1> [6007] 0.00 0.00 129 sigc::internal::slot_call1<sigc::bound_mem_functor1<void, Inkscape::URIReference, SPObject*>, void, SPObject*>::call_it(sigc::internal::slot_rep*, SPObject* const&) <cycle 1> [6225] 0.00 0.00 129 sigc::adaptor_functor<sigc::bound_mem_functor1<void, Inkscape::URIReference, SPObject*> >::deduce_result_type<SPObject* const&, void, void, void, void, void, void>::type sigc::adaptor_functor<sigc::bound_mem_functor1<void, Inkscape::URIReference, SPObject*> >::operator()<SPObject* const&>(SPObject* const&) const <cycle 1> [6226] 0.00 0.00 129 sigc::bound_mem_functor1<void, Inkscape::URIReference, SPObject*>::operator()(SPObject* const&) const <cycle 1> [6228] 0.00 0.00 126 sp_stop_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [6232] 0.00 0.00 101 sp_namedview_set(SPObject*, unsigned int, char const*) <cycle 1> [6301] 0.00 0.00 100 sp_star_set(SPObject*, unsigned int, char const*) <cycle 1> [6304] 0.00 0.00 73 sigc::signal1<void, SPObject*, sigc::nil>::emit(SPObject* const&) const <cycle 1> [6444] 0.00 0.00 67 Inkscape::URIReference::~URIReference() <cycle 1> [6521] 0.00 0.00 50 sp_root_set(SPObject*, unsigned int, char const*) <cycle 1> [6616] 0.00 0.00 42 SPPaintServerReference::~SPPaintServerReference() <cycle 1> [6663] 0.00 0.00 42 SPPaintServerReference::~SPPaintServerReference() <cycle 1> [6664] 0.00 0.00 21 SPFilterReference::~SPFilterReference() <cycle 1> [7119] 0.00 0.00 21 SPFilterReference::~SPFilterReference() <cycle 1> [7120] 0.00 0.00 19 sp_tspan_set(SPObject*, unsigned int, char const*) <cycle 1> [7182] 0.00 0.00 19 sp_text_set(SPObject*, unsigned int, char const*) <cycle 1> [7181] 0.00 0.00 18 sp_radialgradient_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [7221] 0.00 0.00 12 sp_clippath_set(SPObject*, unsigned int, char const*) <cycle 1> [7450] 0.00 0.00 6 sp_metadata_set(SPObject*, unsigned int, char const*) <cycle 1> [8073] 0.00 0.00 4 sp_star_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [8631] 0.00 0.00 2 Inkscape::Preferences::Preferences() <cycle 1> [10292] 0.00 0.00 2 sp_guide_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [9769] 0.00 0.00 1+1 Inkscape::DocumentSubset::Relations::_doRemoveSubtree(SPObject*) <cycle 1> [13194] 0.00 0.00 2 Inkscape::DocumentSubset::Relations::_doRemove(SPObject*) <cycle 1> [10302] 0.00 0.00 2 sigc::internal::slot_call2<sigc::bind_functor<-1, sigc::pointer_functor3<SPObject*, SPObject*, SPDesktop*, void>, SPDesktop*, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil>, void, SPObject*, SPObject*>::call_it(sigc::internal::slot_rep*, SPObject* const&, SPObject* const&) <cycle 1> [10229] 0.00 0.00 2 sigc::bind_functor<-1, sigc::pointer_functor3<SPObject*, SPObject*, SPDesktop*, void>, SPDesktop*, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil>::deduce_result_type<SPObject* const&, SPObject* const&, void, void, void, void, void>::type sigc::bind_functor<-1, sigc::pointer_functor3<SPObject*, SPObject*, SPDesktop*, void>, SPDesktop*, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil, sigc::nil>::operator()<SPObject* const&, SPObject* const&>(SPObject* const&, SPObject* const&) <cycle 1> [10002] 0.00 0.00 2 sigc::adaptor_functor<sigc::pointer_functor3<SPObject*, SPObject*, SPDesktop*, void> >::deduce_result_type<SPObject* const&, SPObject* const&, SPDesktop*&, void, void, void, void>::type sigc::adaptor_functor<sigc::pointer_functor3<SPObject*, SPObject*, SPDesktop*, void> >::operator()<SPObject* const&, SPObject* const&, SPDesktop*&>(SPObject* const&, SPObject* const&, SPDesktop*&) const <cycle 1> [10526] 0.00 0.00 2 sigc::pointer_functor3<SPObject*, SPObject*, SPDesktop*, void>::operator()(SPObject* const&, SPObject* const&, SPDesktop* const&) const <cycle 1> [10530] 0.00 0.00 2 _layer_hierarchy_changed(SPObject*, SPObject*, SPDesktop*) <cycle 1> [9775] 0.00 0.00 2 Inkscape::Preferences::_loadDefaults() <cycle 1> [10291] 0.00 0.00 1 sp_marker_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [12398] 0.00 0.00 1 sp_text_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [12392] 0.00 0.00 1 sp_tspan_build(SPObject*, SPDocument*, Inkscape::XML::Node*) <cycle 1> [12394] 0.00 0.00 1 sigc::internal::slot_call1<sigc::bound_mem_functor1<void, Inkscape::LayerManager, SPObject*>, void, SPObject*>::call_it(sigc::internal::slot_rep*, SPObject* const&) <cycle 1> [13018] 0.00 0.00 1 sigc::adaptor_functor<sigc::bound_mem_functor1<void, Inkscape::LayerManager, SPObject*> >::deduce_result_type<SPObject* const&, void, void, void, void, void, void>::type sigc::adaptor_functor<sigc::bound_mem_functor1<void, Inkscape::LayerManager, SPObject*> >::operator()<SPObject* const&>(SPObject* const&) const <cycle 1> [13666] 0.00 0.00 1 sigc::bound_mem_functor1<void, Inkscape::LayerManager, SPObject*>::operator()(SPObject* const&) const <cycle 1> [13680] 0.00 0.00 1 Inkscape::LayerManager::_selectedLayerChanged(SPObject*) <cycle 1> [13181] 0.00 0.00 1 sigc::internal::slot_call1<sigc::bound_mem_functor1<void, Inkscape::DocumentSubset::Relations, SPObject*>, void, SPObject*>::call_it(sigc::internal::slot_rep*, SPObject* const&) <cycle 1> [13019] 0.00 0.00 1 sigc::adaptor_functor<sigc::bound_mem_functor1<void, Inkscape::DocumentSubset::Relations, SPObject*>
::deduce_result_type<SPObject* const&, void, void, void, void, void,
void>::type sigc::adaptor_functor<sigc::bound_mem_functor1<void, Inkscape::DocumentSubset::Relations, SPObject*> >::operator()<SPObject* const&>(SPObject* const&) const <cycle 1> [13667] 0.00 0.00 1 sigc::bound_mem_functor1<void, Inkscape::DocumentSubset::Relations, SPObject*>::operator()(SPObject* const&) const <cycle 1> [13681] 0.00 0.00 1 Inkscape::DocumentSubset::Relations::_release_object(SPObject*) <cycle 1> [13193] 0.00 0.00 1 Inkscape::LivePathEffect::LPEObjectReference::link(char const*) <cycle 1> [13201] ----------------------------------------------- 0.02 1.85 215263/215263 nr_arena_item_request_render(NRArenaItem*) [7] [9] 35.5 0.02 1.85 215263 nr_arena_request_render_rect(NRArena*, NRRectL*) [9] 0.05 1.17 430526/663464 Inkscape::Preferences::getInt(Glib::ustring const&, int) <cycle 1> [12] 0.02 0.58 215263/663464 Inkscape::Preferences::get() <cycle 1> [340] 0.02 0.00 215263/1236181 nr_object_check_instance_type(void const*, unsigned int) [53] 0.00 0.00 215263/219029 nr_arena_get_type() [2885] ----------------------------------------------- 0.00 1.46 435423/435423 Inkscape::Preferences::getEntry(Glib::ustring const&) [11] [10] 27.8 0.00 1.46 435423 Inkscape::Preferences::_getRawValue(Glib::ustring const&, char const*&) [10] 0.35 1.10 435423/435568 Inkscape::Preferences::_getNode(Glib::ustring const&, bool) [13] 0.00 0.01 432741/28329840 Inkscape::XML::SimpleNode::attribute(char const*) const [16] 0.00 0.00 435423/435530 Inkscape::Preferences::_keySplit(Glib::ustring const&, Glib::ustring&, Glib::ustring&) [2863] -----------------------------------------------
This table describes the call tree of the program, and was sorted by the total amount of time spent in each function and its children.
Each entry in this table consists of several lines. The line with the index number at the left hand margin lists the current function. The lines above it list the functions that called this function, and the lines below it list the functions this one called. This line lists: index A unique number given to each element of the table. Index numbers are sorted numerically. The index number is printed next to every function name so it is easier to look up where the function in the table.
% time This is the percentage of the `total' time that was spent in this function and its children. Note that due to different viewpoints, functions excluded by options, etc, these numbers will NOT add up to 100%.
self This is the total amount of time spent in this function.
children This is the total amount of time propagated into this function by its children.
called This is the number of times the function was called. If the function called itself recursively, the number only includes non-recursive calls, and is followed by a `+' and the number of recursive calls.
name The name of the current function. The index number is printed after it. If the function is a member of a cycle, the cycle number is printed between the function's name and the index number.
For the function's parents, the fields have the following meanings:
self This is the amount of time that was propagated directly from the function into this parent.
children This is the amount of time that was propagated from the function's children into this parent.
called This is the number of times this parent called the function `/' the total number of times the function was called. Recursive calls to the function are not included in the number after the `/'.
name This is the name of the parent. The parent's index number is printed after it. If the parent is a member of a cycle, the cycle number is printed between the name and the index number.
If the parents of the function cannot be determined, the word `<spontaneous>' is printed in the `name' field, and all the other fields are blank.
For the function's children, the fields have the following meanings:
self This is the amount of time that was propagated directly from the child into the function.
children This is the amount of time that was propagated from the child's children to the function.
called This is the number of times the function called this child `/' the total number of times the child was called. Recursive calls by the child are not listed in the number after the `/'.
name This is the name of the child. The child's index number is printed after it. If the child is a member of a cycle, the cycle number is printed between the name and the index number.
If there are any cycles (circles) in the call graph, there is an entry for the cycle-as-a-whole. This entry shows who called the cycle (as parents) and the members of the cycle (as children.) The `+' recursive calls entry shows the number of function calls that were internal to the cycle, and the calls entry for each member shows, for that member, how many times it was called from other members of the cycle.