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 <[email protected]>: > > On 11.09.2014, at 07:14, Tibor Bamhor <[email protected]> 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 <[email protected]>: > >> 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 <[email protected]> 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 <[email protected]> >> Date: 2014-09-10 15:45 GMT+02:00 >> Subject: Re: [Widelands-dev] performance question >> To: Holger Rapp <[email protected]> >> Cc: [email protected] >> >> >> 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 <[email protected]>: >> >>> >>> On 10.09.2014, at 00:50, Tibor Bamhor <[email protected]> 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 : [email protected] >>> > Unsubscribe : https://launchpad.net/~widelands-dev >>> > More help : https://help.launchpad.net/ListHelp >>> >>> >> >> _______________________________________________ >> Mailing list: https://launchpad.net/~widelands-dev >> Post to : [email protected] >> Unsubscribe : https://launchpad.net/~widelands-dev >> More help : https://help.launchpad.net/ListHelp >> >> >> > >
_______________________________________________ Mailing list: https://launchpad.net/~widelands-dev Post to : [email protected] Unsubscribe : https://launchpad.net/~widelands-dev More help : https://help.launchpad.net/ListHelp
