← Back to team overview

widelands-dev team mailing list archive

Re: performance question

 

On 11.09.2014, at 07:14, Tibor Bamhor <tiborb95@xxxxxxxxx> wrote:

> All right, now it was with --opengl=1, results are bit different, though for AI there is no significant difference (8 % now), but the game was shorter.
> 
> In one of my earlier emails I mentioned cmd_queue and it is here indeed - taking 30%.  Main part of this cmd_queue is related to bobs, it seems.

I find the output of your profile hard to read. There are tools for gprof that give you a callgraph visualizing the time spend in each function by size of the graph node. Cmd_queue::run_queue() takes no time at all as far as I can read it, but the program spends 30% of it’s total time in it (which is no wonder, since basically everything in Widelands logic is dispatched as a Command that goes through the queue). You should only look at the “self” column. 


> 
> [1]_____97.1____0.00__124.97_________________main_[1]
> [2]_____97.1____0.00__124.95_______1_________WLApplication::run()_[2]
> [3]_____95.2____0.01__122.48______10_________UI::Panel::run()_[3]
> [4]_____87.2____0.00__112.22_______1_________WLApplication::mainmenu()_[4]
> [5]_____68.1____0.00___87.68_______1_________WLApplication::mainmenu_multiplayer()_[5]
> [6]_____55.6____3.52___68.02___29578+4054464_<cycle_4_as_a_whole>_[6]
> [7]_____39.5____0.01___50.86_______1_________NetHost::run()_[7]
> [8]_____39.5____0.01___50.79___12715+365532__UI::Panel::do_think()_[8]
> [9]_____38.9____0.00___50.06___12325_________Interactive_Base::think()_[9]
> [10]____38.8____0.00___49.95___12325_________Widelands::Game::think()_[10]
> [11]____30.8____0.33___39.27___12325_________Widelands::Cmd_Queue::run_queue()_[11]
> [12]____26.2____0.18___33.52_2975615_________Widelands::Cmd_Act::execute()_[12]
> [13]____24.8____0.07___31.84_2576025_________Widelands::Bob::act()_[13]
> [14]____24.7____0.30___31.47_2530010_________Widelands::Bob::do_act()_[14]
> [15]____22.6____3.01___26.12___12325_________GameRenderer::draw_objects()_<cycle_4>_[15]
> [16]____19.2____0.00___24.70_______1_________Fullscreen_Menu_LaunchMPG::Fullscreen_Menu_LaunchMPG()_[16]
> [17]____19.1____0.00___24.52_______1_________Fullscreen_Menu_LaunchMPG::change_map_or_save()_[17]
> [18]____17.7____2.24___20.59_9833290+60076979_<cycle_9_as_a_whole>_[18]
> [19]____17.2____0.02___22.14___12325_________GameRendererGL::draw()_<cycle_4>_[19]
> [20]____15.3____0.68___18.98_7385892_________RenderTarget::drawanim()_[20]
> [21]____15.1____1.79___17.60__244640_________void_Widelands::Map::find_reachable<Widelands::FindImmovablesCallback>(Widelands
> [22]____13.4____0.52___16.78_5059151_________()_c
> [23]____12.4____0.27___15.69__134647_________Widelands::Map::findpath(Widelands::Coords,_Widelands::Coords,_int,_Widelands::P
> [24]____12.0____3.27___12.12_2225850789_________std::unique_ptr<Widelands::Field_[],_std::default_delete<Widelands::Field_[]>
> [25]____11.8____0.02___15.21__125059_________Widelands::Bob::start_task_movepath()
> [26]____10.9____0.01___14.03___12325_________GameRendererGL::prepare_terrain_dither()_[26]
> [27]____10.9____1.14___12.83___24650_________GameRendererGL::collect_terrain_dither()_[27]
> [28]____10.5____0.21___13.29_5091607_________()_const_[28]
> [29]____10.2____0.01___13.08_______1_________Widelands::Game::run()_[29]
> [30]____10.1____0.40___12.58_3276377_________ImageTransformations::player_colored()_[30]
> [31]____10.1____0.02___12.93__201687_________Widelands::Critter::roam_update()_[31]
> [32]_____9.5____0.00___12.27_______1_________Fullscreen_Menu_LaunchMPG::select_map()_[32]
> [33]_____9.4____3.07____9.05_2225850789______ZSt3getILj0EJPN9Widelands5FieldESt14default_deleteIA_S1_EEENSt11__add_c_refI
> [34]_____8.4____0.90____9.85_217827528_______Widelands::Map::get_neighbour()_const_[34]
> [35]_____8.3____0.00___10.70___12754_________UI::Panel::handle_tooltip()_[35]
> [36]_____8.3____0.00___10.70___12565+15430___UI::Panel::do_tooltip()_[36]
> [37]_____8.3____0.00___10.69___12754_________UI::Panel::draw_tooltip()_[37]
> [38]_____8.1____0.01___10.37___12517_________NetHost::think()_[38]
> [39]_____8.0____0.01___10.33___24650_________DefaultAI::think()_[39]
> 
> As for compilation flags, I am using this:
> (INSDIR is custom target directory)
> 
> cmake ../.. -DCMAKE_BUILD_TYPE=Debug \
> -DCMAKE_INSTALL_PREFIX=$INSDIR \
> -DWL_INSTALL_PREFIX=$INSDIR \
> -DWL_INSTALL_DATADIR=share/widelands \
> -DWL_INSTALL_BINDIR=bin'
> -DCMAKE_C_FLAGS=-pg -DCMAKE_CXX_FLAGS=-pg
> 
> What should I change here for more accurate profiling?
> 
> 2014-09-11 15:26 GMT+02:00 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


Follow ups

References