Profiling DarkRadiant

**greebo** · December 4, 2007

I managed to get a working profile build including proper gmon.out analysis. My first stress-test was in bonehoard.map (~13000 primitives, 1100 entities), and I inverted the selection about 7 or 8 times, i.e. I selected and deselected everything multiple times.

The profile log is quite interesting. There are a lot of STL-related functions on the top of the list, but also a few GraphTreeModel, ModuleSystem and shared_* (presumably related to boost::shared_ptr) functions:

  7.47	 44.77	17.66 900079445	 0.00	 0.00  std::_List_const_iterator<scene::Instance*>::operator++()
 5.81	 58.51	13.74 164729408	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::find(std::string const&) const
 4.36	 68.82	10.31 522489147	 0.00	 0.00  boost::detail::atomic_increment(int*)
 4.18	 78.70	 9.89 522969651	 0.00	 0.00  boost::detail::atomic_exchange_and_add(int*, int)
 3.78	 87.64	 8.94	67085	 0.00	 0.00  std::reverse_iterator<std::_List_iterator<scene::Instance*> > std::__find<std::reverse_iterator<std::_List_iterator<scene::Instance*> >, scene::Instance*>(std::reverse_iterator<std::_List_iterator<scene::Instance*> >, std::reverse_iterator<std::_List_iterator<scene::Instance*> >, scene::Instance* const&, std::input_iterator_tag)
 2.48	 93.51	 5.87 900170130	 0.00	 0.00  std::reverse_iterator<std::_List_iterator<scene::Instance*> >::base() const
 2.08	 98.44	 4.93 1223455886	 0.00	 0.00  std::less<std::string>::operator()(std::string const&, std::string const&) const
 2.07	103.34	 4.90 1232393326	 0.00	 0.00  bool std::operator< <char, std::char_traits<char>, std::allocator<char> >(std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)
 1.91	107.85	 4.51   289212	 0.00	 0.00  graph_tree_model_get_path(_GtkTreeModel*, _GtkTreeIter*)
 1.77	112.03	 4.18 164720113	 0.00	 0.00  module::ModuleRegistry::getModule(std::string const&) const
 1.76	116.19	 4.16 899968875	 0.00	 0.00  std::_List_iterator<scene::Instance*>::operator--()
 1.70	120.20	 4.02 1054517805	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::_S_key(std::_Rb_tree_node<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > const*)
 1.47	123.68	 3.48 596888352	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::_S_right(std::_Rb_tree_node_base const*)
 1.46	127.13	 3.45 457625257	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::_S_left(std::_Rb_tree_node_base const*)
 1.38	130.39	 3.26 450017980	 0.00	 0.00  bool std::operator==<std::_List_iterator<scene::Instance*> >(std::reverse_iterator<std::_List_iterator<scene::Instance*> > const&, std::reverse_iterator<std::_List_iterator<scene::Instance*> > const&)
 1.34	133.56	 3.17 1054517805	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::_S_value(std::_Rb_tree_node<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > const*)
 1.10	136.17	 2.61 522966911	 0.00	 0.00  boost::detail::shared_count::~shared_count()
 1.05	138.66	 2.49   403765	 0.00	 0.00  ui::TextureBrowser::evaluateHeight()
 1.05	141.14	 2.48 450207435	 0.00	 0.00  std::_List_iterator<scene::Instance*>::operator==(std::_List_iterator<scene::Instance*> const&) const
 1.03	143.57	 2.44 522755721	 0.00	 0.00  boost::detail::sp_counted_base::release()
 1.00	145.94	 2.37 231545701	 0.00	 0.00  std::_Rb_tree_iterator<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> >::operator++()
 0.98	148.26	 2.32 128393452	 0.00	 0.00  GlobalShaderSystem()
 0.98	150.57	 2.31 314422668	 0.00	 0.00  boost::detail::shared_count::shared_count(boost::detail::shared_count const&)
 0.97	152.87	 2.30 449950895	 0.00	 0.00  std::_List_iterator<scene::Instance*>::operator*() const
 0.92	155.05	 2.18 522458218	 0.00	 0.00  boost::detail::sp_counted_base::add_ref_copy()
 0.91	157.20	 2.15 232082269	 0.00	 0.00  std::_Rb_tree_iterator<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> >::operator!=(std::_Rb_tree_iterator<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> > const&) const
 0.88	159.27	 2.08 924929905	 0.00	 0.00  std::_List_const_iterator<scene::Instance*>::operator!=(std::_List_const_iterator<scene::Instance*> const&) const
 0.85	161.27	 2.00 450017980	 0.00	 0.00  bool std::operator!=<std::_List_iterator<scene::Instance*> >(std::reverse_iterator<std::_List_iterator<scene::Instance*> > const&, std::reverse_iterator<std::_List_iterator<scene::Instance*> > const&)
 0.84	163.25	 1.98 1219248661	 0.00	 0.00  std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >::operator()(std::pair<std::string const, boost::shared_ptr<RegisterableModule> > const&) const
 0.83	165.21	 1.96 449950895	 0.00	 0.00  std::reverse_iterator<std::_List_iterator<scene::Instance*> >::operator*() const
 0.78	167.06	 1.85 329458868	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::end() const
 0.73	168.79	 1.73 494188276	 0.00	 0.00  std::_Rb_tree_const_iterator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >::_Rb_tree_const_iterator(std::_Rb_tree_node<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > const*)
 0.66	170.36	 1.57 164729408	 0.00	 0.00  std::_Rb_tree_const_iterator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >::operator!=(std::_Rb_tree_const_iterator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > const&) const
 0.63	171.86	 1.50 232082269	 0.00	 0.00  std::map<std::pair<std::string, boost::shared_ptr<scene::INode> >, GraphTreeNode*, std::less<std::pair<std::string, boost::shared_ptr<scene::INode> > >, std::allocator<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> > >::end()
 0.63	173.34	 1.48   134170	 0.00	 0.00  std::iterator_traits<std::_List_const_iterator<scene::Instance*> >::difference_type std::__distance<std::_List_const_iterator<scene::Instance*> >(std::_List_const_iterator<scene::Instance*>, std::_List_const_iterator<scene::Instance*>, std::input_iterator_tag)
 0.60	174.75	 1.41 232417638	 0.00	 0.00  std::_Rb_tree<std::pair<std::string, boost::shared_ptr<scene::INode> >, std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*>, std::_Select1st<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> >, std::less<std::pair<std::string, boost::shared_ptr<scene::INode> > >, std::allocator<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> > >::end()
 0.55	176.05	 1.30 449883810	 0.00	 0.00  std::reverse_iterator<std::_List_iterator<scene::Instance*> >::operator++()
 0.54	177.33	 1.28 164729408	 0.00	 0.00  std::map<std::string, boost::shared_ptr<RegisterableModule>, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::find(std::string const&) const
 0.52	178.55	 1.22 164729408	 0.00	 0.00  std::_Rb_tree_const_iterator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >::operator==(std::_Rb_tree_const_iterator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > const&) const
 0.51	179.74	 1.20 165476129	 0.00	 0.00  boost::detail::shared_count::shared_count()
 0.50	180.93	 1.19 164729358	 0.00	 0.00  module::RegistryReference::getRegistry()
 0.50	182.11	 1.18 164729356	 0.00	 0.00  boost::shared_ptr<RegisterableModule>::operator=(boost::shared_ptr<RegisterableModule> const&)
 0.48	183.25	 1.14 165671894	 0.00	 0.00  boost::detail::shared_count::operator=(boost::detail::shared_count const&)
 0.48	184.39	 1.14 232082269	 0.00	 0.00  GraphTreeNode::end()
 0.47	185.49	 1.10 232403783	 0.00	 0.00  std::_Rb_tree_iterator<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> >::operator*() const
 0.45	186.55	 1.06 24703703	 0.00	 0.00  std::_List_const_iterator<scene::Instance*>::operator*() const
 0.45	187.61	 1.06 164729408	 0.00	 0.00  boost::shared_ptr<RegisterableModule>::operator RegisterableModule* boost::shared_ptr<RegisterableModule>::*() const
 0.44	188.66	 1.05 164729408	 0.00	 0.00  std::map<std::string, boost::shared_ptr<RegisterableModule>, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::end() const
 0.43	189.67	 1.01 164729356	 0.00	 0.00  boost::shared_ptr<RegisterableModule>::shared_ptr()
 0.41	190.65	 0.98		2	 0.49	 0.49  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::_M_rightmost()
 0.41	191.61	 0.96 164729356	 0.00	 0.00  std::_Rb_tree_const_iterator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >::operator->() const
 0.40	192.55	 0.95 42653662	 0.00	 0.00  ui::TextureBrowser::shaderIsVisible(boost::shared_ptr<IShader>)
 0.39	193.48	 0.93 164729359	 0.00	 0.00  module::RegistryReference::Instance()
 0.39	194.40	 0.92 164729408	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::_M_end() const
 0.38	195.29	 0.90 128393454	 0.00	 0.00  boost::shared_ptr<ShaderSystem>::operator*() const
 0.37	196.17	 0.88 42658399	 0.00	 0.00  string_length(char const*)
 0.37	197.05	 0.88 128393454	 0.00	 0.00  boost::shared_ptr<ShaderSystem>::shared_ptr<RegisterableModule>(boost::shared_ptr<RegisterableModule> const&, boost::detail::static_cast_tag)
 0.36	197.91	 0.86 128393454	 0.00	 0.00  boost::shared_ptr<ShaderSystem> boost::static_pointer_cast<ShaderSystem, RegisterableModule>(boost::shared_ptr<RegisterableModule> const&)
 0.36	198.75	 0.84							 _Unwind_IteratePhdrCallback
 0.36	199.59	 0.84   134170	 0.00	 0.00  Signal1<Selectable const&>::operator()(Selectable const&) const
 0.35	200.42	 0.83 174746694	 0.00	 0.00  boost::shared_ptr<Texture>::operator->() const
 0.35	201.25	 0.83   201255	 0.00	 0.00  std::reverse_iterator<std::_List_iterator<scene::Instance*> >::reverse_iterator(std::reverse_iterator<std::_List_iterator<scene::Instance*> > const&)
 0.35	202.07	 0.82 233264460	 0.00	 0.00  std::_Rb_tree_iterator<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> >::_Rb_tree_iterator(std::_Rb_tree_node<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> >*)
 0.34	202.88	 0.82 33780378	 0.00	 0.00  GlobalOpenGL()
 0.34	203.69	 0.81 164730149	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::_S_key(std::_Rb_tree_node_base const*)
 0.34	204.50	 0.81 50872066	 0.00	 0.00  ui::TextureBrowser::getTextureHeight(boost::shared_ptr<Texture>)
 0.32	205.26	 0.76		2	 0.38	 0.38  std::allocator<std::_Rb_tree_node<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >(std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > const&)
 0.32	206.01	 0.75 164729408	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::_M_begin() const
 0.27	206.65	 0.64 25436033	 0.00	 0.00  ui::TextureBrowser::nextTexturePos(ui::TextureLayout&, boost::shared_ptr<Texture>, int*, int*)
 0.25	207.25	 0.60 164720387	 0.00	 0.00  boost::shared_ptr<RegisterableModule>::~shared_ptr()
 0.24	207.81	 0.56							 std::iterator_traits<std::_List_const_iterator<Selectable*> >::iterator_category std::__iterator_category<std::_List_const_iterator<Selectable*> >(std::_List_const_iterator<Selectable*> const&)
 0.22	208.33	 0.53 42653662	 0.00	 0.00  shader_equal_prefix(char const*, char const*)
 0.22	208.85	 0.52							 execute_cfa_program
 0.21	209.35	 0.50 25436033	 0.00	 0.00  ui::TextureBrowser::getTextureWidth(boost::shared_ptr<Texture>)
 0.20	209.83	 0.48 164730149	 0.00	 0.00  std::_Rb_tree<std::string, std::pair<std::string const, boost::shared_ptr<RegisterableModule> >, std::_Select1st<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > >, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::_S_value(std::_Rb_tree_node_base const*)
 0.20	210.31	 0.48   213930	 0.00	 0.00  boost::detail::sp_counted_base::weak_release()
 0.19	210.77	 0.46 50872066	 0.00	 0.00  boost::shared_ptr<Texture>::shared_ptr(boost::shared_ptr<Texture> const&)
 0.19	211.23	 0.46   122370	 0.00	 0.00  std::_List_iterator<scene::Instance*>::operator++()
 0.19	211.67	 0.44 93922734	 0.00	 0.00  boost::shared_ptr<IShader>::operator->() const
 0.18	212.10	 0.43							 uw_update_context_1
 0.18	212.52	 0.42							 boost::shared_ptr<Texture>::operator!() const
 0.18	212.94	 0.42 128393454	 0.00	 0.00  boost::shared_ptr<ShaderSystem>::~shared_ptr()
 0.17	213.34	 0.41   670850	 0.00	 0.00  ListDetail::ListIterator<ListDetail::ConstTraits<SignalHandler1<Selectable const&> > >::operator!=(ListDetail::ListIterator<ListDetail::ConstTraits<SignalHandler1<Selectable const&> > > const&) const
 0.17	213.75	 0.41							 std::map<std::string, int, std::less<std::string>, std::allocator<std::pair<std::string const, int> > >::key_comp() const
 0.16	214.12	 0.37 24703703	 0.00	 0.00  std::_List_const_iterator<scene::Instance*>::operator++(int)
 0.15	214.48	 0.37 51141243	 0.00	 0.00  int const& std::max<int>(int const&, int const&)
 0.15	214.84	 0.36		1	 0.36	 0.36  module::ModuleRegistry::initialiseContext(int, char**)
 0.15	215.20	 0.36 85499883	 0.00	 0.00  boost::shared_ptr<IShader>::~shared_ptr()
 0.14	215.54	 0.34 101919188	 0.00	 0.00  boost::shared_ptr<Texture>::~shared_ptr()
 0.14	215.88	 0.34 164720114	 0.00	 0.00  module::GlobalModuleRegistry()
 0.14	216.21	 0.34 33779976	 0.00	 0.00  ui::TextureBrowser::getFontHeight()
 0.14	216.53	 0.32   525039	 0.00	 0.00  RadiantSelectionSystem::foreachSelected(SelectionSystem::Visitor const&) const
 0.12	216.81	 0.28 42653662	 0.00	 0.00  boost::shared_ptr<IShader>::shared_ptr(boost::shared_ptr<IShader> const&)
 0.11	217.08	 0.27 42887678	 0.00	 0.00  boost::shared_ptr<IShader>::operator IShader* boost::shared_ptr<IShader>::*() const
 0.11	217.35	 0.27 33780378	 0.00	 0.00  boost::shared_ptr<OpenGLBinding> boost::static_pointer_cast<OpenGLBinding, RegisterableModule>(boost::shared_ptr<RegisterableModule> const&)
 0.11	217.62	 0.27							 read_uleb128
 0.11	217.88	 0.26 15686600	 0.00	 0.00  BasicVector3<double>::BasicVector3(double const&, double const&, double const&)
 0.11	218.13	 0.25							 uw_frame_state_for
 0.10	218.37	 0.25 25436033	 0.00	 0.00  ui::TextureBrowser::getFilter()
 0.10	218.61	 0.24 33780378	 0.00	 0.00  boost::shared_ptr<OpenGLBinding>::shared_ptr<RegisterableModule>(boost::shared_ptr<RegisterableModule> const&, boost::detail::static_cast_tag)
 0.10	218.85	 0.24	 8538	 0.00	 0.00  std::numeric_limits<unsigned int>::max()
 0.09	219.06	 0.21   213709	 0.00	 0.00  GlobalShaderCache()
 0.09	219.27	 0.21	  104	 0.00	 0.00  std::map<std::string, boost::shared_ptr<RegisterableModule>, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::key_comp() const
 0.09	219.48	 0.21	  104	 0.00	 0.00  std::map<std::string, boost::shared_ptr<RegisterableModule>, std::less<std::string>, std::allocator<std::pair<std::string const, boost::shared_ptr<RegisterableModule> > > >::lower_bound(std::string const&)
 0.08	219.68	 0.20 18588672	 0.00	 0.00  bool __gnu_cxx::operator!=<boost::shared_ptr<scene::INode> const*, std::vector<boost::shared_ptr<scene::INode>, std::allocator<boost::shared_ptr<scene::INode> > > >(__gnu_cxx::__normal_iterator<boost::shared_ptr<scene::INode> const*, std::vector<boost::shared_ptr<scene::INode>, std::allocator<boost::shared_ptr<scene::INode> > > > const&, __gnu_cxx::__normal_iterator<boost::shared_ptr<scene::INode> const*, std::vector<boost::shared_ptr<scene::INode>, std::allocator<boost::shared_ptr<scene::INode> > > > const&)
 0.08	219.87	 0.19	16151	 0.00	 0.00  GraphTreeNode::erase(std::_Rb_tree_iterator<std::pair<std::pair<std::string, boost::shared_ptr<scene::INode> > const, GraphTreeNode*> >)
 0.08	220.05	 0.18 24850460	 0.00	 0.00  std::list<scene::Instance*, std::allocator<scene::Instance*> >::end() const
 0.08	220.23	 0.18 17386856	 0.00	 0.00  std::less<boost::detail::sp_counted_base*>::operator()(boost::detail::sp_counted_base* const&, boost::detail::sp_counted_base* const&) const
 0.07	220.40	 0.18 34208530	 0.00	 0.00  __gnu_cxx::__normal_iterator<boost::shared_ptr<scene::INode> const*, std::vector<boost::shared_ptr<scene::INode>, std::allocator<boost::shared_ptr<scene::INode> > > >::operator*() const
 0.07	220.57	 0.17 33780378	 0.00	 0.00  boost::shared_ptr<OpenGLBinding>::operator*() const
 0.07	220.74	 0.17		6	 0.03	 0.03  boost::shared_ptr<Resource>::operator Resource* boost::shared_ptr<Resource>::*() const
 0.06	220.89	 0.15							 _Unwind_Find_FDE
 0.06	221.04	 0.15							 read_encoded_value_with_base
 0.06	221.18	 0.15 42653662	 0.00	 0.00  shader_equal_n(char const*, char const*, unsigned int)
 0.06	221.33	 0.15  8093080	 0.00	 0.00  std::vector<boost::shared_ptr<scene::INode>, std::allocator<boost::shared_ptr<scene::INode> > >::begin() const
 0.06	221.47	 0.14	   11	 0.01	 0.01  boost::shared_ptr<IPreferenceSystem>::~shared_ptr()
 0.06	221.61	 0.14 42653662	 0.00	 0.00  string_equal_nocase_n(char const*, char const*, unsigned int)
 0.06	221.75	 0.14							 uw_install_context_1
 0.05	221.88	 0.13 24716290	 0.00	 0.00  SelectionList<scene::Instance>::end() const
 0.05	222.01	 0.13 23397261	 0.00	 0.00  BasicVector3<double>::x() const
 0.05	222.13	 0.13 18865039	 0.00	 0.00  BasicVector3<double>::z()

I gather from the log that there is a GlobalShaderSystem() call (that is, 128 millions of calls) involved somewhere. Also, 33 millions of calls to GlobalOpenGL().

std::_rb_Tree stuff, which is presumably related to std::map lookups: 164 million calls taking up nearly a minute?

RegisterableModule-related stuff is called a lot. I guess this backs up your suggestion of caching the Global*() references locally to avoid lookups. I already thought about caching the raw references in the Global*() accessors instead of the shared_ptrs, this would ease the destruction-delay problem due to shared_ptrs held. Dangling references are not that much of a problem, because calls to Global*() would crash after modulesystem shutdown anyway due to an assertion I placed in there.

Also, I see a lot of shared_count cropping up. I think this is due to our practice of passing shared_ptr objects by value almost always, causing many calls to copy constructors. I guess we can safely change a few occurrences to pass the shared_ptr's as reference-to-const, where appropriate. I can see shared_ptr constructors of IShader, Texture, ShaderSystem and ShaderCache, a few dozen millions each. This could be reduced, I guess.

ui::TextureBrowser::evaluateHeight - wtf? A suspicion of mine is that there is some callback ending up in the Texture browser when selections are inverted, causing recalculations of the TextureBrowser's height?

As a next step, I'll try to implement an automated test routine into DarkRadiant, triggered by a flag in the XMLRegistry. This flag would cause DR to open a specific map, do a few commands and shutdown again, saving the gmon.out file. This way I can monitor any progress due to code changes.

OrbWeaver · December 4, 2007

I'm guessing that the uppermost function (operator++) is something in the Scenegraph, the implementation is really piss-poor structurally and performance-wise (I made a couple of very minor changes based on profiling, but the thing needs to be rewritten as we all know).

Also, I see a lot of shared_count cropping up. I think this is due to our practice of passing shared_ptr objects by value almost always, causing many calls to copy constructors. I guess we can safely change a few occurrences to pass the shared_ptr's as reference-to-const, where appropriate. I can see shared_ptr constructors of IShader, Texture, ShaderSystem and ShaderCache, a few dozen millions each. This could be reduced, I guess.

Yes, that can be an issue; in a couple of cases in the renderer I have changed a function to accept a raw pointer to avoid the shared-count stuff (but only when the profiling indicates this should be done, and it must be commented to explain why it's not a shared_ptr).

ui::TextureBrowser::evaluateHeight - wtf? A suspicion of mine is that there is some callback ending up in the Texture browser when selections are inverted, causing recalculations of the TextureBrowser's height?

Sounds familiar, this was an issue during map load as well (every new brush required a new shader which updated the Textures window which recalculated the height for the entire window). If you can figure out where this is happening (use the call-graph section of the profile) you can call the relevant function I added to disabled texture window updates temporarily.

As a next step, I'll try to implement an automated test routine into DarkRadiant, triggered by a flag in the XMLRegistry. This flag would cause DR to open a specific map, do a few commands and shutdown again, saving the gmon.out file. This way I can monitor any progress due to code changes.

That sounds like a good idea, but it might be hard to capture some of the major cases -- such as creating a few hundred models and dragging the view around a lot to trigger render calls. The issue with profiling is that you need to make the operation of interest dominant in the profile, otherwise you will waste time looking at functions called during startup.

**greebo** · December 5, 2007

I have a basic automated profile run implemented now, see debug.xml:

<debug>
<automatedTest>
	<runTest value="1" />
	<testMap value="/media/HDD/Games/Doom3/darkmod/maps/bonehoard.map" />
	<testCommands>
		<testCommand value="InvertSelection" count="8" />
	</testCommands>
</automatedTest>
</debug>

This automatically loads the bonehoard map, executes the command InvertSelection 8 times and exits, saving the gmon.out file. Also, I let the detailed timings dumped to the console:

Running automated test...
Loading map: /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map
[ScopedDebugTimer] "Loaded map /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map" in 108.732
--- Executing command InvertSelection 8 times
[ScopedDebugTimer] "Executing command InvertSelection" in 120.514
[ScopedDebugTimer] "Executing command InvertSelection" in 152.831
[ScopedDebugTimer] "Executing command InvertSelection" in 110.852
[ScopedDebugTimer] "Executing command InvertSelection" in 159.162
[ScopedDebugTimer] "Executing command InvertSelection" in 109.907
[ScopedDebugTimer] "Executing command InvertSelection" in 167.142
[ScopedDebugTimer] "Executing command InvertSelection" in 108.024
[ScopedDebugTimer] "Executing command InvertSelection" in 151.948
[ScopedDebugTimer] "---Executed command InvertSelection 8 times" in 1114.03
[ScopedDebugTimer] "Executed all commands" in 1114.03

I guess the fluctuation of the InvertSelection timings (110 vs. 160 seconds) is due to the slower rendering when everything is highlighted.

Anyways, now I can start looking into this and evaluate my changes. I'll save each gprof output I create for later reference as well.

**greebo** · December 5, 2007

I changed the GlobalShaderCache() accessor to cache a static reference to the ShaderCache and behold:

Running automated test...
Loading map: /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map
[ScopedDebugTimer] "Loaded map /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map" in 98.5345
--- Executing command InvertSelection 8 times
[ScopedDebugTimer] "Executing command InvertSelection" in 63.1348
[ScopedDebugTimer] "Executing command InvertSelection" in 99.6585
[ScopedDebugTimer] "Executing command InvertSelection" in 54.9065
[ScopedDebugTimer] "Executing command InvertSelection" in 113.796
[ScopedDebugTimer] "Executing command InvertSelection" in 56.1299
[ScopedDebugTimer] "Executing command InvertSelection" in 109.259
[ScopedDebugTimer] "Executing command InvertSelection" in 63.6634
[ScopedDebugTimer] "Executing command InvertSelection" in 103.748
[ScopedDebugTimer] "---Executed command InvertSelection 8 times" in 695.658
[ScopedDebugTimer] "Executed all commands" in 695.659

The timings were cut down to almost two thirds. A look into the flat profile doesn't list the GlobalShaderCache in the top ranks anymore and many of the std::_rb_tree calls are gone now.

I'll go ahead and optimise all Global*() accessors now and run another test.

OrbWeaver · December 5, 2007

Didn't you determine that using a static shared_ptr in the Global accessors caused problems though? Or do you mean you intend to optimise the calling code to cache its own reference?

**greebo** · December 5, 2007

Yes, holding shared_ptrs is still evil, but I changed the accessors to this:

inline INamespace& GlobalNamespace() {
// Cache the reference locally
static INamespace& _namespace(
	*boost::static_pointer_cast<INamespace>(
		module::GlobalModuleRegistry().getModule(MODULE_NAMESPACE)
	)
);
return _namespace;

Instead of a shared_ptr, I cache the reference only.

**greebo** · December 5, 2007

It's getting better. I changed all Global*() accessors to cache their references and now it takes about 40% of the time it took during the first test run:

Running automated test...
Loading map: /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map
[ScopedDebugTimer] "Loaded map /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map" in 103.156
--- Executing command InvertSelection 8 times
[ScopedDebugTimer] "Executing command InvertSelection" in 39.5221
[ScopedDebugTimer] "Executing command InvertSelection" in 81.271
[ScopedDebugTimer] "Executing command InvertSelection" in 37.3005
[ScopedDebugTimer] "Executing command InvertSelection" in 85.832
[ScopedDebugTimer] "Executing command InvertSelection" in 46.1742
[ScopedDebugTimer] "Executing command InvertSelection" in 89.269
[ScopedDebugTimer] "Executing command InvertSelection" in 44.1362
[ScopedDebugTimer] "Executing command InvertSelection" in 89.1711
[ScopedDebugTimer] "---Executed command InvertSelection 8 times" in 542.583
[ScopedDebugTimer] "Executed all commands" in 542.583

I'll commit that change and look at the flat profile again to get a grip of that TextureBrowser weirdness.

OrbWeaver · December 5, 2007

Instead of a shared_ptr, I cache the reference only.

That's also evil unfortunately, you are holding a reference to a heap-allocated object which may be deleted. The very existence of a "dangling" reference causes the program to be Undefined, IIRC.

I think the semantics of the accessor functions should be that if the module has been unloaded or destroyed, it should return an empty shared_ptr (which can at least be checked for validity), rather than an invalid reference which will almost certainly cause an immediate segfault with no opportunity for error-checking.

Still, this looks like an important performance issue and should definitely be solved, even if this means rewriting the calling code rather than the accessor functions.

**greebo** · December 5, 2007

The TextureBrowser gets notified very often by GlobalShaderSystem() via the activeShadersChanged() callback. Disabling this, cuts the time down to 20 seconds instead of 40 seconds, including the slow rendering. I'll have to investigate why the activeShadersChanged() call is necessary and why it is called so often.

**greebo** · December 5, 2007

That's also evil unfortunately, you are holding a reference to a heap-allocated object which may be deleted. The very existence of a "dangling" reference causes the program to be Undefined, IIRC.

I think the semantics of the accessor functions should be that if the module has been unloaded or destroyed, it should return an empty shared_ptr (which can at least be checked for validity), rather than an invalid reference which will almost certainly cause an immediate segfault with no opportunity for error-checking.

Still, this looks like an important performance issue and should definitely be solved, even if this means rewriting the calling code rather than the accessor functions.

Dangling references are of course not nice, but even without storing references, the access to the Global*() stuff after Module shutdown would crash the program immediately, because I placed an assertion in the ModuleRegistry. Accessing Global*() stuff after modulesystem shutdown is not allowed and will crash the program in any case.

Of course, the debugging is harder.

If we can fix it in another way, that's of course fine by me as well. This can go gradually over time, I reckon.

OrbWeaver · December 5, 2007

Dangling references are of course not nice, but even without storing references, the access to the Global*() stuff after Module shutdown would crash the program immediately, because I placed an assertion in the ModuleRegistry. Accessing Global*() stuff after modulesystem shutdown is not allowed and will crash the program in any case.

OK, so there's no way the dangling reference would ever be returned, because the assertion would fire first? In that case I guess it is OK because the undefined code would never actually be reached.

EDIT: Except of course that an assertion would not happen in a release build, this should really be a std::logic_error exception instead of an assertion (if it isn't already).

**greebo** · December 5, 2007

OK, so there's no way the dangling reference would ever be returned, because the assertion would fire first? In that case I guess it is OK because the undefined code would never actually be reached.

Ok sorry, I misremembered, I just checked the code and this is how the ModuleRegistry reacts:

Let's assume any calling code tries to access the GlobalShaderSystem() after modulesystem shutdown. During shutdown, the map containing the named modules gets cleared, meaning that the lookup for the ShaderSystem module fails. The ModuleRegistry returns an empty shared_ptr (NULL) - this leads straight into a crash. Not throwing any exceptions.

This was before my recent change. The currently active code stores a static reference. After module shutdown, the reference is invalid and accessing it leads to undefined behaviour (i.e. crash). The ModuleRegistry is queried only once, so there is no way to intercept the call and throw exceptions.

So in either case, accessing Global*() stuff after modulesystem shutdown would crash the application.

What about storing weak_ptrs? Are the lock() routines slow?

Apart from that, the only straight-forward way is to optimise the calling code to store references, but wouldn't this lead to the same issues as now?

OrbWeaver · December 5, 2007

Let's assume any calling code tries to access the GlobalShaderSystem() after modulesystem shutdown. During shutdown, the map containing the named modules gets cleared, meaning that the lookup for the ShaderSystem module fails. The ModuleRegistry returns an empty shared_ptr (NULL) - this leads straight into a crash. Not throwing any exceptions.
This was before my recent change. The currently active code stores a static reference. After module shutdown, the reference is invalid and accessing it leads to undefined behaviour (i.e. crash). The ModuleRegistry is queried only once, so there is no way to intercept the call and throw exceptions.

I think the problem here is that there is a design mismatch between the behaviour of the ModuleRegistry and the behaviour of the accessor functions. The ModuleRegistry expects to return an empty shared_ptr if a module is not found, and the calling code to deal with this; the accessor functions on the other hand expect that the module will always be valid, and return a reference (i.e. a de-referenced shared_ptr) to the calling code.

I suspect one of two things needs to happen to remedy this: EITHER the module registry also considers that looking up a missing module is an invalid operation and throws an exception, OR the accessor functions have to assume that the returned shared_ptr could be NULL and do not dereference this automatically. The first option does allow for the static cache optimisation, but does not allow for the possible future existence of optional modules which is something I think would be beneficial (i.e. the particles module could be optional, if it is not available the Select Particle button is not displayed etc).

EDIT: Actually throwing an exception does allow for optional modules, as long as a custom exception class was written e.g. ModuleNotFoundException, rather than std::logic_error.

**greebo** · December 5, 2007

I suspect one of two things needs to happen to remedy this: EITHER the module registry also considers that looking up a missing module is an invalid operation and throws an exception, OR the accessor functions have to assume that the returned shared_ptr could be NULL and do not dereference this automatically. The first option does allow for the static cache optimisation, but does not allow for the possible future existence of optional modules which is something I think would be beneficial (i.e. the particles module could be optional, if it is not available the Select Particle button is not displayed etc).

Hm, I think I don't get it. How could the reference be cached if the ModuleRegistry is to be invoked each time by the accessor? Would it be something like this?

// This is the accessor for the registry
inline IClipper& GlobalClipper() {

module::GlobalModuleRegistry().checkStatus(); // throws exceptions if modules are unavailable

// Cache the reference locally
static IClipper&  _clipper(
	*boost::static_pointer_cast<IClipper>(
		module::GlobalModuleRegistry().getModule(MODULE_CLIPPER)
	)
);
return _clipper;
}

**greebo** · December 5, 2007

Heh, I just recompiled using a release build and the difference is really noticeable in large maps. It takes 4 seconds to invert the selection on my system - it took much longer before.

There are two more possible candidates for improvement: The TextureBrowser and the GraphTreeModel. Both are cropping up a lot when it comes to selection changes. The GraphTreeModel hooks itself in the Instances by directly placing a callback "childSelectedChanged". This is probably causing the additional, slow scenegraph traversals we've been experiencing.

I'm not sure what to do about both. The GraphTreeModel probably has to be rewritten from scratch, the TextureBrowser could do with some update deferral.

**greebo** · December 5, 2007

And another candidate for optimisation: I've found out why the first InvertSelection call is so much faster than the second one. The RadiantSelectionSystem keeps track of all selected instances, which is implemented as a std::list. Of course, appending elements to std::list is quite fast, but removal is horribly slow.

That's why selecting all 14000 brushes takes 18 seconds in a profile build, but deselecting takes nearly 55 seconds (each deselected element is looked up in the std::list which is running in linear time).

OrbWeaver · December 5, 2007

Hm, I think I don't get it. How could the reference be cached if the ModuleRegistry is to be invoked each time by the accessor?

I guess it couldn't, but didn't you say that there was an assertion that fired if the module could not be retrieved? My suggestion at this stage is little more than changing this assertion to an exception, so at least calling code could intercept and deal with the problem (and facilitate optional modules) rather than just crashing the application.

I'm not sure what to do about both. The GraphTreeModel probably has to be rewritten from scratch, the TextureBrowser could do with some update deferral.

Yeah, at the very least the "create-on-demand" suggestion I made yesterday for the GraphTreeModel should help with the fact that it is contantly being updated and slowing things down. Not sure about the texture window though, does the call graph information provide any clues as to what is causing this?

Of course, appending elements to std::list is quite fast, but removal is horribly slow.

I guess you mean searching a list -- removal should actually be constant time. There are plenty of instances where GtkRadiant developers did not understand that linear searches are SLOW.

**greebo** · December 5, 2007

I guess it couldn't, but didn't you say that there was an assertion that fired if the module could not be retrieved? My suggestion at this stage is little more than changing this assertion to an exception, so at least calling code could intercept and deal with the problem (and facilitate optional modules) rather than just crashing the application.

I misremembered about the assertion. In earlier version of the ModuleRegistry, the assertion was there, but it got removed later on, because of initialisation-order issues (IIRC).

Anyway, where should the assertion be positioned, when the reference is cached? Should it be done like in the code sample I posted above or somehow else?

Yeah, at the very least the "create-on-demand" suggestion I made yesterday for the GraphTreeModel should help with the fact that it is contantly being updated and slowing things down.

I guess for small maps this would be acceptable. I'm wondering whether this would be practical in maps like bonehoard with 13k+ map elements. I guess populating such a GtkTreeModel is more than just slow, that's probably why the GtkRadiant people settled for instant-updating.

Another problem is the Selection-status-update. This is tightly bound to the scene::Instances now, which notify the GraphTreeModel on each change. I'm really not sure how this could be accomplished in a faster way while keeping the functionality intact.

Not sure about the texture window though, does the call graph information provide any clues as to what is causing this?

To be honest, I haven't figured out what the call graph is supposed to show. Is this some sort of call stack? The function lists don't make sense at all, they seem to appear in random order. :mellow:

I guess you mean searching a list -- removal should actually be constant time. There are plenty of instances where GtkRadiant developers did not understand that linear searches are SLOW.

Yes, I was referring to the erase() method which makes use of the std::find() algorithm.

I already thought about replacing that, but there are of course complications. We need a structure that

- stores pointers to scene::Instances

- has fast append() routines

- provides fast lookup to allow for fast removal

- provides insertion order information.

The last point is the tricky one. The GlobalSelectionSystem().getUltimateSelec

ted() and getPenUltimateSelected() routines rely on a SelectionList::back() method. This is especially important for the "entity connect" command and "stitch patch textures", for instance.

OrbWeaver · December 5, 2007

Anyway, where should the assertion be positioned, when the reference is cached? Should it be done like in the code sample I posted above or somehow else?

Hmm, it looks like there is indeed no way to have the exception-throwing (or any other error-detecting) behaviour if the reference is cached, unfortunately. You could try using the weak_ptr, but I don't know how well this works across DLLs.

I guess for small maps this would be acceptable. I'm wondering whether this would be practical in maps like bonehoard with 13k+ map elements. I guess populating such a GtkTreeModel is more than just slow, that's probably why the GtkRadiant people settled for instant-updating.

I don't suppose it would be that slow, given that the entire scenegraph is traversed for every frame during a render. Moreover, the performance impact is already there now -- it's just instead of being concentrated in the (presumably rare) event of an Entity List display, it's spread out through every selection operation ever made.

To be honest, I haven't figured out what the call graph is supposed to show. Is this some sort of call stack? The function lists don't make sense at all, they seem to appear in random order.

Yes, it is confusing at first but once you learn how to read it it is very useful. The Gprof documentation should explain what all the columns mean.

I already thought about replacing that, but there are of course complications. We need a structure that
- stores pointers to scene::Instances
- has fast append() routines
- provides fast lookup to allow for fast removal
- provides insertion order information.

For the new scenegraph I suggest building our own tree, since trying to hack it with existing STL containers won't be sufficient. This means each Node would have a reference to its parent, a list of references to its children, and would be contained within a wrapper (manager) class which could also maintain any necessary maps required for quick lookup of Nodes.

**greebo** · December 5, 2007

For the new scenegraph I suggest building our own tree, since trying to hack it with existing STL containers won't be sufficient. This means each Node would have a reference to its parent, a list of references to its children, and would be contained within a wrapper (manager) class which could also maintain any necessary maps required for quick lookup of Nodes.

I wasn't referring to the scenegraph, but to the SelectionSystem's list of instances. The RadiantSelectionSystem class maintains its own list of instances and its terribly slow when it comes to lookups.

I already have a working replacement for the SelectionList template, basing on a std::multimap and its definitely faster than the existing implementation. A selection inversion in the bonehoard only takes 3 seconds (selection) and 3-4 seconds (de-selection).

I'll commit it soon, so you can take a look at it.

**greebo** · December 5, 2007

The latest profile run says this:

Running automated test...
Loading map: /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map
[ScopedDebugTimer] "Loaded map /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map" in 109.587
--- Executing command InvertSelection 5 times
[ScopedDebugTimer] "Executing command InvertSelection" in 14.5047
[ScopedDebugTimer] "Executing command InvertSelection" in 12.775
[ScopedDebugTimer] "Executing command InvertSelection" in 10.7645
[ScopedDebugTimer] "Executing command InvertSelection" in 12.7595
[ScopedDebugTimer] "Executing command InvertSelection" in 10.8703
[ScopedDebugTimer] "---Executed command InvertSelection 5 times" in 90.1474
[ScopedDebugTimer] "Executed all commands" in 90.1481

Compare this against the first profile run.

Tels · December 5, 2007

The latest profile run says this:

Running automated test...
Loading map: /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map
[ScopedDebugTimer] "Loaded map /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map" in 109.587
--- Executing command InvertSelection 5 times
[ScopedDebugTimer] "Executing command InvertSelection" in 14.5047
[ScopedDebugTimer] "Executing command InvertSelection" in 12.775
[ScopedDebugTimer] "Executing command InvertSelection" in 10.7645
[ScopedDebugTimer] "Executing command InvertSelection" in 12.7595
[ScopedDebugTimer] "Executing command InvertSelection" in 10.8703
[ScopedDebugTimer] "---Executed command InvertSelection 5 times" in 90.1474
[ScopedDebugTimer] "Executed all commands" in 90.1481

Compare this against the first profile run.

Yeehaw You are my hero

Now, can you cut down the loading time, too? Oh, I also noticed shutting down DR with such a big map takes quite a lot of time, too.

New Horizon · December 5, 2007

The latest profile run says this:

Running automated test...
Loading map: /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map
[ScopedDebugTimer] "Loaded map /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map" in 109.587
--- Executing command InvertSelection 5 times
[ScopedDebugTimer] "Executing command InvertSelection" in 14.5047
[ScopedDebugTimer] "Executing command InvertSelection" in 12.775
[ScopedDebugTimer] "Executing command InvertSelection" in 10.7645
[ScopedDebugTimer] "Executing command InvertSelection" in 12.7595
[ScopedDebugTimer] "Executing command InvertSelection" in 10.8703
[ScopedDebugTimer] "---Executed command InvertSelection 5 times" in 90.1474
[ScopedDebugTimer] "Executed all commands" in 90.1481

Compare this against the first profile run.

Ha ha, wow. That's quite the difference. Great work!!

**greebo** · December 6, 2007

Thanks, N.H. and Tels!

I rewrote the GraphTreeModel (mostly from scratch). The EntityList is only reacting to updates when it is visible, this saves a lot of time. Also, I changed the underlying data structure to a std::map. These are the timings:

Loading map: /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map
[ScopedDebugTimer] "Loaded map /media/HDD/Games/Doom3/darkmod/maps/bonehoard.map" in 89.6673
--- Executing command InvertSelection 6 times
[ScopedDebugTimer] "Executing command InvertSelection" in 5.08551
[ScopedDebugTimer] "Executing command InvertSelection" in 7.05532
[ScopedDebugTimer] "Executing command InvertSelection" in 4.9649
[ScopedDebugTimer] "Executing command InvertSelection" in 7.43277
[ScopedDebugTimer] "Executing command InvertSelection" in 5.03966
[ScopedDebugTimer] "Executing command InvertSelection" in 7.11566
[ScopedDebugTimer] "---Executed command InvertSelection 6 times" in 66.6595
--- Executing command EntityList 1 times
[ScopedDebugTimer] "Executing command EntityList" in 1.16476
[ScopedDebugTimer] "---Executed command EntityList 1 times" in 1.26473
--- Executing command InvertSelection 6 times
[ScopedDebugTimer] "Executing command InvertSelection" in 6.53192
[ScopedDebugTimer] "Executing command InvertSelection" in 8.78281
[ScopedDebugTimer] "Executing command InvertSelection" in 6.62156
[ScopedDebugTimer] "Executing command InvertSelection" in 7.60446
[ScopedDebugTimer] "Executing command InvertSelection" in 5.40898
[ScopedDebugTimer] "Executing command InvertSelection" in 7.50509
[ScopedDebugTimer] "---Executed command InvertSelection 6 times" in 45.8593
--- Executing command EntityList 1 times
[ScopedDebugTimer] "Executing command EntityList" in 0.004126
[ScopedDebugTimer] "---Executed command EntityList 1 times" in 0.294128
--- Executing command InvertSelection 6 times
[ScopedDebugTimer] "Executing command InvertSelection" in 5.02595
[ScopedDebugTimer] "Executing command InvertSelection" in 7.08956
[ScopedDebugTimer] "Executing command InvertSelection" in 4.95798
[ScopedDebugTimer] "Executing command InvertSelection" in 7.00134
[ScopedDebugTimer] "Executing command InvertSelection" in 4.93948
[ScopedDebugTimer] "Executing command InvertSelection" in 8.01297
[ScopedDebugTimer] "---Executed command InvertSelection 6 times" in 40.345
[ScopedDebugTimer] "Executed all commands" in 154.425

The test routine is like this:

- Call InvertSelection 6 times

- Show EntityList

- Call InvertSelection 6 times

- Hide EntityList

- Call InvertSelection 6 times

The timings are much better now (by a factor of two to three), compared to the previous GraphTreeModel.

OrbWeaver · December 6, 2007

A vast improvement. I don't recall though, does the ScopedDebugTimer report timings in seconds or milliseconds?

Profiling DarkRadiant

Recommended Posts

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Link to comment

Share on other sites

Join the conversation

Recent Status Updates