1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.
  2. Hey Guest, is it this your first time on the forums?

    Visit the Beginner's Box

    Introduce yourself, read some of the ins and outs of the community, access to useful links and information.

    Dismiss Notice

New profiler in build 2409

Discussion in 'Modding [KAG]' started by Asu, Nov 21, 2017.

Thread Status:
Not open for further replies.
  1. Asu

    Asu THD Team THD Team Forum Moderator

    Messages:
    1,580
    A new profiler was introduced in build 2409 so it is easier for contributors and modders to spot performance bottlenecks in KAG.
    It replaces the functionality of the older profiler. You can use it to measure performance of your scripts and engine tasks.

    Using the profiler
    As usual, measurements are activated when setting /g_measureperformance 1, and deactivated when setting /g_measureperformance 0.
    Performance listings are done with the /performance command. When starting the game, g_measureperformance is automatically disabled.

    What's new?
    Timer precision
    For now, the Windows and macOS builds use the same timer as before. However, the Linux build uses accurate per-thread timers. This means that, Linux client and dedicated server performance measurements will be generally more accurate, in particular for tasks with small run times, but with large call counts. You may also encounter less noise when other tasks consume a lot of CPU power too.

    Overhead
    Though it works a similar way to the older profiler, the performance overhead of the profiler should be lower because as few things are performed for collecting data as possible.

    Flushing measurements
    You may now flush performance measurements using /performanceflush. When run, all profile data collected so far is cleared, and performance data will be collected again.

    Performance dump overhaul
    Code:
    [19:41:20]  20.6%  1.3% [  30.903,  0.000]  5911358x -- <cblob:update:components>
    [19:41:20]  1.3%  1.3% [  1.938,  0.000]  12106x -- void onRender(CRules@ this):ctf_interface
    [19:41:20]  1.6%  1.6% [  2.408,  0.000]  12126x -- <cmap:update:colors>
    [19:41:20]  45.9%  1.6% [  68.800,  0.000]  12126x -- <cblob:update>
    [19:41:20]  2.1%  2.1% [  3.215,  0.000]  127947x -- void onTick(CBlob@ this):spikes
    [19:41:20]  2.2%  2.2% [  3.286,  0.000]  12106x -- void onRender(CRules@ this):killmessages
    [19:41:20]  2.4%  2.4% [  3.621,  0.000]  12149571x -- <cblob:spritelayer>
    [19:41:20]  2.5%  2.5% [  3.726,  0.000]  12106x -- <cparticle:render:back>
    [19:41:20]  2.5%  2.5% [  3.790,  0.000]  5414585x -- <cblob:update:shape>
    [19:41:20]  31.0%  3.0% [  46.490,  0.000]  4031479x -- <scripts>
    [19:41:20]  3.0%  3.0% [  4.459,  0.000]  249212x -- void onTick(CSprite@ this):runnerhead
    [19:41:20]  12.2%  3.0% [  18.273,  0.000]  5911358x -- <cblob:ontick:script>
    [19:41:20]  3.7%  3.7% [  5.567,  0.000]  198644x -- void onTick(CMovement@ this):runnermovement
    [19:41:20]  15.2%  3.7% [  22.796,  0.000]  5414336x -- <cblob:sprite:update>
    [19:41:20]  27.9%  5.5% [  41.825,  0.000]  6049512x -- <cblob:dotick>
    [19:41:20]  6.1%  5.9% [  9.204,  0.001]  12126x -- <cmap:physics:box2d>
    [19:41:20]  12.1%  11.1% [  18.101,  0.001]  12172x -- <cnet:update:client>
    [19:41:20]  30.5%  20.9% [  45.696,  0.000]  245986x -- <cirrlichttask:render>
      ^  ^  ^  ^  ^  ^- name of the task
      |  |  |  |  \------------- amount of task runs
      |  |  |  \-------------------------- average execution time (total/runs), seconds
      |  |  \------------------------------------- total execution time, seconds
      |  \----------------------------------------------- exclusive execution time, over the total execution time (minus idle)
      \------------------------------------------------------ total execution time, over the total execution time (minus idle)
    
    [19:41:20] %total %excl  [  total,  average]
    [19:41:20] Profiled 518 tasks (438 ignored), 73287027 samples.
                ^  ^  ^- amount of task runs measured
                |  \--------------- tasks ignored, because their total runtime was too small
          \-------------------------- unique tasks profiled in total
    
    profilerdetail.png

    Engine tasks are wrapped with <> and appear in gray in the developer console.
    Script hook tasks are written in the form : hooksignature:script, and appear in yellow in the developer console.

    Tasks and exclusive times
    The exclusive time of a task is the time spent exclusively by a task : Its total execution time, minus the total execution time of all of its children tasks.
    For example, void "onTick(CBlob@ this):blobplacement" is a(n indirect) child of <cblob:dotick>.
    The <scripts> task is a convenience task that measures the execution of all scripts, so you can see approximatively what time is spent into your scripts.

    You may see this in your performance dump:
    Code:
     25.98% of total performance time was not associated with any task.
    This means that some engine tasks were not profiled properly, which generally happens when compiling scripts, for example, because we do not define tasks for everything.

    Profiler fine-tuning
    The new performance profiler has a new experimental /g_measureperformance_interval setting, disabled by default.
    When set to 1 or more, it is the amount of measurements skipped in a row. For example, if set to 5, the profiler will correctly measure one sample, then ignore 5, and so on. Because of how the profiler works, this may render exclusive execution time calculations inaccurate.
    This may save CPU power, though, which is useful when running the profiler over extended periods. This setting should not be modified while a measurement is in progress, because it will invalidate current measurements. You should run /performanceflush when you do this.

    In the future, it may be possible to profile script functions directly for specific scripts, on a per-function basis.
    If there is interest for a performance graph and/or if modders would like a graph class, it may be implemented into the future.
     
    Last edited: Nov 21, 2017
  2. Furai

    Furai THD Team THD Team Administrator

    Messages:
    3,124
    Pinned and locked. If you need additional help ask for it in separate thread. This one will be used as reference.
     
Thread Status:
Not open for further replies.