widelands-dev team mailing list archive

[Holger Rapp <HolgerRapp@xxxxxxx>]

you should probably start out by using opengl instead of the software renderer - it is swamping your profile. Then, you should sort by “self”, not by “all” or “time”. That is the information which function takes the most time, not how much time is spend inside a function in total.

Also, I think you are using a debug build (due to the many seconds spend in unique_ptr<> delete). For profiling you want to have an optimized (but non-stripped) build. 

Cheers,
Holger 

On 11.09.2014, at 06:22, Tibor Bamhor <tiborb95@xxxxxxxxx> wrote:

> So I opted for gprof and bellow are the results. They are from 3 hours-long game (AI only) on Crater map (red player was eliminated by blue one). You can look at it, what is interested for me is that DefaultAI (line 43) - the main AI function - takes only 6.3 % of total CPU if gprof is correct.
> 
> If somebody want raw data (txt file) let me know.
> 
> I believe that proportion of functions changes with size of map.
> 
> ==================== Call graph () ====================
> [see second column - % time]
> 
> 
> index_%_time____self__children____called_____name
> 
> [1]_____99.4____0.00_1696.26_________________main_[1]
> [2]_____99.4____0.01_1696.18_______1_________WLApplication::run()_[2]
> [3]_____99.0____0.03_1689.50______10_________UI::Panel::run()_[3]
> [4]_____89.4____0.00_1525.92_______1_________WLApplication::mainmenu()_[4]
> [5]_____71.7___14.77_1208.34__123188+10361143_<cycle_3_as_a_whole>_[5]
> [6]_____69.6____0.00_1187.91_______1_________WLApplication::mainmenu_multiplayer()_[6]
> [7]_____53.6____0.02__914.58___61226_________GameRendererSDL::draw()_<cycle_3>_[7]
> [8]_____53.6____2.27__912.31___61226_________GameRendererSDL::draw_terrain()_[8]
> [9]_____52.5____0.64__894.67_63185232________GameRendererSDL::draw_field()_[9]
> [10]____52.3____1.87__891.10_63185232________void_draw_field_int<unsigned_int>()_[10]
> [11]____39.9____0.00__680.96_______1_________NetHost::run()_[11]
> [12]____31.2___16.13__515.46_126370464_______void_render_triangle<unsigned_int>()_[12]
> [13]____30.2__407.08__107.54_126370464_______void_render_edge_lists<unsigned_int>()_[13]
> [14]____29.3__114.19__385.34_271118424_______std::unique_ptr<Widelands::Field_[],_std::default_delete<Widelands::Field_[]>_
> [15]____27.3____0.04__465.86___61569+2233150_UI::Panel::do_think()_[15]
> [16]____27.2____0.03__463.78___61226_________Interactive_Base::think()_[16]
> [17]____27.2____0.05__463.44___61226_________Widelands::Game::think()_[17]
> [18]____22.6__101.56__283.78_271118424_______ZSt3getILj0EJPN9Widelands5FieldESt14default_deleteIA_S1_EEENSt11__add_c_refIN
> [19]____20.8____0.68__353.99___61226_________Widelands::Cmd_Queue::run_queue()_[19]
> [20]____19.9____0.25__339.93_5582271_________Widelands::Cmd_Act::execute()_[20]
> [21]____19.9____4.48__334.90_17335297+131869067_<cycle_8_as_a_whole>_[21]
> [22]____19.8____0.00__338.65_______1_________Fullscreen_Menu_LaunchMPG::Fullscreen_Menu_LaunchMPG()_[22]
> [23]____19.8____0.00__337.97_______1_________Fullscreen_Menu_LaunchMPG::change_map_or_save()_[23]
> [24]____19.7____0.20__336.18_4731494_________Widelands::Bob::act()_[24]
> [25]____19.7____0.49__335.58_4618069_________Widelands::Bob::do_act()_[25]
> [26]____19.6__334.54____0.00_896797820_______SDLSurface::get_pixels()_const_[26]
> [27]____19.3____4.02__325.94__638674_________void_Widelands::Map::find_reachable<Widelands::FindImmovablesCallback>()_<cycle_
> [28]____16.6__103.91__179.87_271118424_______std::__add_c_ref<Widelands::Field*>::type_std::__get_helper<0u,_Widelands::Fie
> [29]____15.2____2.26__256.88_564713957_______Widelands::Map::get_neighbour()_const_[29]
> [30]____12.4___13.32__198.39___61226_________GameRenderer::draw_objects()_<cycle_3>_[30]
> [31]____12.0____0.54__203.58__213382_________Widelands::Map::findpath()_[31]
> [32]____11.1____0.03__189.65__197613_________Widelands::Bob::start_task_movepath()__[32]
> [33]____10.5__101.56___78.31_271118424_______ZNSt11_Tuple_implILj0EJPN9Widelands5FieldESt14default_deleteIA_S1_EEE7_M_head
> [34]____10.0____0.00__171.01_______1_________Widelands::Game::run()_[34]
> [35]_____9.9____0.00__169.01_______1_________Fullscreen_Menu_LaunchMPG::select_map()_[35]
> [36]_____8.5___11.77__132.94_17897783________void_render_road_vert<unsigned_int>()_[36]
> [37]_____8.2____0.03__140.70__279850_________Widelands::Critter::roam_update()_[37]
> [38]_____8.0____0.02__135.69__199605_________Widelands::Worker::program_update()_[38]
> [39]_____6.7____9.60__104.72_7781675_________void_render_road_horiz<unsigned_int>()_[39]
> [40]_____6.6____0.00__111.96___14488_________Widelands::Map::find_reachable_fields()_[40]
> [41]_____6.6____0.30__111.67___14488_________void_Widelands::Map::find_reachable<Widelands::FindNodesCallback>()_[41]
> [42]_____6.3____0.07__106.93___61424_________NetHost::think()_[42]
> [43]_____6.3____0.01__106.74__122452_________DefaultAI::think()_[43]
> 
> 
> 
> 
> __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.
> 
> 
> ================ top functions sorted by "self" column ==============
> 
> 
> [13]____30.2__407.08__107.54_126370464_________void_render_edge_lists<unsigned_int>()_[13]
> [26]____19.6__334.54____0.00_896797820_________SDLSurface::get_pixels()_const_[26]
> [14]____29.3__114.19__385.34_271118424_________std::unique_ptr<Widelands::Field_[],_std::default_delete<Widelands::Field_[]>_
> [28]____16.6__103.91__179.87_271118424_________std::__add_c_ref<Widelands::Field*>::type_std::__get_helper<0u,_Widelands::Fie
> [33]____10.5__101.56___78.31_271118424_________ZNSt11_Tuple_implILj0EJPN9Widelands5FieldESt14default_deleteIA_S1_EEE7_M_head
> [18]____22.6__101.56__283.78_271118424_________ZSt3getILj0EJPN9Widelands5FieldESt14default_deleteIA_S1_EEENSt11__add_c_refIN
> [45]_____4.6___78.31____0.00_271118424_________std::_Head_base<0u,_Widelands::Field*,_false>::_M_head()_[45]
> 
> 
> 
> ---------- Forwarded message ----------
> From: Tibor Bamhor <tiborb95@xxxxxxxxx>
> Date: 2014-09-10 15:45 GMT+02:00
> Subject: Re: [Widelands-dev] performance question
> To: Holger Rapp <HolgerRapp@xxxxxxx>
> Cc: widelands-dev@xxxxxxxxxxxxxxxxxxx
> 
> 
> any volunteer? :)
> 
> It would be ideal if profiling could be done within some late interval, I mean skipping like first 2 hours and then profile for 10 minutes.
> 
> But from my random testing of backtrace (stopping of the game in random time), it seems that "cmd_queue" is taking quite a long of time during game near-freezes.
> 
> Perhaps it relates to number of bobs or non-player objects.
> 
> I googled for some fiendly profiler, but it is not that simple...
> 
> 2014-09-10 15:35 GMT+02:00 Holger Rapp <HolgerRapp@xxxxxxx>:
> 
> On 10.09.2014, at 00:50, Tibor Bamhor <tiborb95@xxxxxxxxx> wrote:
> 
> > Hi,
> >
> > when working on AI I look on performance as well.
> >
> > I also encountered game sudden slow-downs when fps drops below 1 or so. Using printfs I found that in such situation AI is not called for few seconds at all. So it seems it is not a culprit.
> >
> > But my question is about other observation - the game with big map 512x512 - PAUSED and fps still shows ~13 fps - instead of expected 25.0. No movement on screen of course. So what can the game be doing so cpu intensive when paused?
> 
> No one can tell without profiling. You need to profile.
> 
> 
> >
> > Regards
> > _______________________________________________
> > Mailing list: https://launchpad.net/~widelands-dev
> > Post to     : widelands-dev@xxxxxxxxxxxxxxxxxxx
> > Unsubscribe : https://launchpad.net/~widelands-dev
> > More help   : https://help.launchpad.net/ListHelp
> 
> 
> 
> _______________________________________________
> Mailing list: https://launchpad.net/~widelands-dev
> Post to     : widelands-dev@xxxxxxxxxxxxxxxxxxx
> Unsubscribe : https://launchpad.net/~widelands-dev
> More help   : https://help.launchpad.net/ListHelp

Attachment: smime.p7s
Description: S/MIME cryptographic signature