widelands-dev team mailing list archive

[Tibor Bamhor <tiborb95@xxxxxxxxx>]

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.


[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
>
>
>