widelands-dev team mailing list archive

[Tibor Bamhor <tiborb95@xxxxxxxxx>]

For me this output is satisfactory. Because I understand "hierarchy" of
functions in AI.

The main finding for me is that "management of roads" consumes biggest
portion of CPU time used by AI. I will have to look at it sometimes later.

Also percent of CPU spent by AI is a good information for me. I expected it
would be like 50 % but this is not the case. At least in the test I had run
so far the highest percent was 16. But I need to run also some really
long-time and big world tests, The percent will be much higher I expect.



2014-09-13 18:53 GMT+02:00 Holger Rapp <HolgerRapp@xxxxxxx>:

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