Analyzing CPU usage by using profile analyzer

Hello,

I am working on a project that uses profiler output to characterize CPU usage.
In profiler, the CPU usage is categorized under 9 different subcategories.
The image below shows these categories
6734524--775477--upload_2021-1-17_20-46-3.png

As much as I understand, profıler collects data based on marker points, and it associates execution time with those markers.

I am wondering that are there any documents that describe which marker names are associated with CPU usage subcategories?

I would like to know how much CPU time my application spent during rendering, physics, scripting, and other categories.

For example,
I collected profiler data and then I managed to get the marker table by using Profile Analyzer. You can find the marker table in attachments and named as marker.zip. I had to zip the file because of xlsx file format.

I managed to calculate CPU time during physics-related operation by filtering the following markers;

  • Physics.Simulate
  • Physics.JointBreaks
  • Physics.UpdateCloth
  • Physics.Interpolation
  • Physics.TriggerEnterExits
  • Physics.TriggerStays
  • Physics.Contacts
  • Physics.FetchResults
  • Physics.UpdateBodies
  • Physics.ProcessReports
  • Physics.Processing
  • Physics.ProcessingCloth

Based on this page, section: Physics markers.

On the same page, it says that Rendering and VSync markers are given as;

  • WaitForTargetFPS

  • Gfx.ProcessCommands

  • Gfx.WaitForCommands

  • Gfx.PresentFrame

  • Gfx.WaitForPresentOnGfxThread

  • Gfx.WaitForRenderThread

However, I am not sure which markers indicate rendering and which ones indicate vsync. Also, I did not have the all markers listed above in my log file.
In the table below, you can check markers exist in my log file. Could you please explain why I cannot observe some markers on my log files?

6734524--775540--upload_2021-1-17_21-45-53.png

I reviewed this page and this page. However, I could not get a precise answer.

My unity version is Version 2019.4.15f1 (fbf367ac14e9) Personal.

If my post is in the wrong forum section, I would be very grateful if you transfer it to the right place.

Thank you.
Have a nice day.

6734524–775537–marker.zip (64.6 KB)

Hi there,
That sounds like an interesting project. :slight_smile:
Let’s see if I can help somewhat with that.

Not as that no. The pages you linked to are the most extensive documentation of profiler markers we have.
However, we’ve greatly extended the profiler API in 2020.1 and .2 so that now You could use HierarchyFrameDataView.GetItemCategoryIndex or RawFrameDataView.GetSampleCategoryIndex to get the category of a particular sample. Profile Analyzer uses RawFrameDataView from 2020.1 upwards btw.

If you want a list of markers and their categories, In 2020.2 we added ProfilerRecorder API and the ProfilerRecorderDescription contains the Category. Sou you can use ProfilerRecorderHandle.GetAvailable to get all markers currently known to the system, which might require that you caused them to get logged to the profiler data stream because whatever they indicated happened. Note that this is a runtime profiler API so it relates to the profiler status in a Player or Play Mode and not to what the Profiler might have collected from an attached Player, but it also means this is available for profiler overlays in your app.

Because these happen on the Render Thread and you likely filtered Profile Analyzer to the main thread. BTW, the CPU Usage Chart is only showing the summed up times for each category based on leaf samples on the main thread. Samples categorized as Internal are “see through”, so if you imagine you’d be trapped in 2D space in Timeline view and looking up at the main thread data, the colors you see are the ones making up the chart, except for grey, which is transparent and the category of the sample above it is used for he chart. (Or if you use RawFrameDataView and check the Begin and end times for each sample, attribute the time to that category and then re-attribute any time spend in subsequent samples that overlaps this time to their categories)

  • WaitForTargetFPS (vSync, Main)

  • Gfx.ProcessCommands (Rendering, Render Thread)

  • Gfx.WaitForCommands (Internal,
    Render Thread)

  • Gfx.PresentFrame (Rendering, can partially include vSync times, no indication as to how much currently, Render Thread)

  • Gfx.WaitForPresentOnGfxThread (Rendering, Main)

  • Gfx.WaitForRenderThread (Rendering, used alternative to the above in older versions, Main)

So that last one is for versions before 2019.3 iirc and basically a rename of the one above.

Now, most of this is only available in 2020.x BUT, the profiler can record and open data from older versions. So you can build your profiling tooling on 2020.2 and still keep any game or other app development on 2019.4, as long as you don’t rely on the run-time APIs like ProfilerRecorder.

Also, in a similar vein to the other new APIs, in 2021.1 we’ve exposed the ProfilerWindow class and some functions to set and get the selection of the CPU and GPU modules.

Please let me know if there’s anything else I can help with or anything missing for you with this. Though I must admit I’m now kinda curious how the end result of what you re building will look like and what workflows it would enable. We have some ideas to improve the profiler that could go in a similar direction and, as you can see with the API exposure over the last versions, are building up to making the Profiler more extensibile right now.

Cheers from a fellow profiler developer,
Martin

1 Like

Hi Martin,

Thank you for your detailed explanation.
Actually, I am new to game development environments.

I installed Unity 2020.2 and tried to use Profiler Recorder. As far as I see, this script provides enough data for my study.
However, I could not get values. It seems that it is never updated.

I am using Windridge City sample project. Here is the script code I used.
Which game object I should append this script to?

using System.Collections;
using System.Collections.Generic;
using UnityEngine;
using System.IO;
using Unity.Profiling;
using System.Text;

public class ProfilerAnalysis : MonoBehaviour
{

    string statsText;
    ProfilerRecorder systemMemoryRecorder;
    ProfilerRecorder gcMemoryRecorder;
    ProfilerRecorder mainThreadTimeRecorder;
    ProfilerRecorder renderRecorder;
    ProfilerRecorder physicsRecorder;
    ProfilerRecorder scriptRecorder;

    // Start is called before the first frame update
    void Start()
    {
        Debug.Log("I am alive!");
    }


    static double GetRecorderFrameAverage(ProfilerRecorder recorder)
    {
        var samplesCount = recorder.Capacity;
        if (samplesCount == 0)
            return 0;

        double r = 0;
       
        var samples = new List <ProfilerRecorderSample>(samplesCount);
        recorder.CopyTo(samples);
        for (var i = 0; i < samples.Count; ++i)
            r += samples[i].Value;
        r /= samplesCount;
     

        return r;
    }

    void OnEnable()
    {
        systemMemoryRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Memory, "System Used Memory");
        gcMemoryRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Memory, "GC Reserved Memory");
        mainThreadTimeRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Internal, "Main Thread", 15);
        renderRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Render, "Rendering Time");
        physicsRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics Time");
        scriptRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Scripts, "Physics Time");
    }

    void OnDisable()
    {
        systemMemoryRecorder.Dispose();
        gcMemoryRecorder.Dispose();
        mainThreadTimeRecorder.Dispose();
        renderRecorder.Dispose();
        physicsRecorder.Dispose();
        scriptRecorder.Dispose();
    }

    void Update()
    {
        var sb = new StringBuilder(500);
        sb.AppendLine($"Frame Time: {GetRecorderFrameAverage(mainThreadTimeRecorder) * (1e-6f):F1} ms and its unit type {mainThreadTimeRecorder.UnitType}");
        sb.AppendLine($"GC Memory: {gcMemoryRecorder.LastValue / (1024 * 1024)} MB");
        sb.AppendLine($"System Memory: {systemMemoryRecorder.LastValue / (1024 * 1024)} MB");
        sb.AppendLine($"Rendering Time: {renderRecorder.LastValue} ");
        sb.AppendLine($"Physics Time: {physicsRecorder.LastValue} ");
        sb.AppendLine($"Script Time: {scriptRecorder.LastValue} ");
        statsText = sb.ToString();
        Debug.Log(statsText);

    }

    void OnGUI()
    {
        GUI.TextArea(new Rect(10, 30, 250, 250), statsText);
    }
}

Thank you again for your response.
Have a nice day.

Testing this snippet on a very recent version I get values for systemMemoryRecorder, gcMemoryRecorder and mainThreadTimeRecorder. There are no counters named "Rendering Time", or "Physics Time" so those are not just reporting 0, they are not reporting anything (.Count = 0) and aren’t valid (.Valid == false). So I assume you did not find these name & category combination through ProfilerRecorderHandle.GetAvailable?

You’ll need to find relevant base samples for these timings on the main thread, e.g.:

    void OnEnable()
    {
        systemMemoryRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Memory, "System Used Memory");
        gcMemoryRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Memory, "GC Reserved Memory");
        mainThreadTimeRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Internal, "Main Thread", 15);
        physicsRecorder = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics.Processing", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        physicsRecorder1 = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics.Simulate", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        physicsRecorder2 = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics.SyncRigidbodyTransform", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        physicsRecorder3 = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics.SyncColliderTransform", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        physicsRecorder4 = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics.UpdateVehicles", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        physicsRecorder5 = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics.FetchResults", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        physicsRecorder6 = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics.UpdateBodies", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        physicsRecorder7 = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics.ProcessReports", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        physicsRecorder8 = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics2D.Simulate", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        physicsRecorder9 = ProfilerRecorder.StartNew(ProfilerCategory.Physics, "Physics.Interpolation", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        //// or, rougher estimate:
        var playerLoopCategory = new ProfilerCategory("PlayerLoop");
        physicsRecorder10 = ProfilerRecorder.StartNew(playerLoopCategory, "FixedUpdate.PhysicsFixedUpdate");
        physicsRecorder11 = ProfilerRecorder.StartNew(playerLoopCategory, "FixedUpdate.Physics2DFixedUpdate");
        physicsRecorder12 = ProfilerRecorder.StartNew(playerLoopCategory, "PreUpdate.PhysicsUpdate");
        physicsRecorder13 = ProfilerRecorder.StartNew(playerLoopCategory, "PreUpdate.Physics2DUpdate");


        renderRecorderMainThread = ProfilerRecorder.StartNew(ProfilerCategory.Internal, "Camera.Render", options: ProfilerRecorderOptions.CollectOnlyOnCurrentThread);
        renderRecorderAllThreads = ProfilerRecorder.StartNew(ProfilerCategory.Internal, "Camera.Render");
        StartCoroutine(LogRecordableItems());
    }

    IEnumerator LogRecordableItems()
    {
        yield return null;

        var handles = new List<ProfilerRecorderHandle>();
        ProfilerRecorderHandle.GetAvailable(handles);
        var sb = new StringBuilder();
       
        foreach (var handle in handles)
        {
            var statDesc = ProfilerRecorderHandle.GetDescription(handle);
            sb.AppendFormat("{1} - {0}\n", statDesc.Name, statDesc.Category);
            // 8000 is a critical threshold for strings/logs, try not to overstep that
            if(sb.Length > 7900)
            {
                // flush
                Debug.Log(sb.ToString());
                sb.Clear();
            }

        }
        Debug.Log(sb.ToString());
    }

and for rough Main thread Render and Render Thread timings:

        sb.AppendLine($"Rendering Time: {renderRecorderMainThread.LastValue * (1e-6f):F1} ms");
        sb.AppendLine($"Render Thread time: {(renderRecorderAllThreads.LastValue - renderRecorderMainThread.LastValue) * (1e-6f):F1} ms");
var playerLoopCategory = new ProfilerCategory("PlayerLoop");
        physicsRecorder10 = ProfilerRecorder.StartNew(playerLoopCategory, "FixedUpdate.PhysicsFixedUpdate");
        physicsRecorder11 = ProfilerRecorder.StartNew(playerLoopCategory, "FixedUpdate.Physics2DFixedUpdate");
        physicsRecorder12 = ProfilerRecorder.StartNew(playerLoopCategory, "PreUpdate.PhysicsUpdate");
        physicsRecorder13 = ProfilerRecorder.StartNew(playerLoopCategory, "PreUpdate.Physics2DUpdate");

The code you mentioned does not seem to return any values for me, they are all 0.0.
I am getting Draw Calls and Vertices Count successfully, but the PlayerLoop values are all not working for me in 2021.2.f11. Is there any more documentation on this? This forum thread is the only thing that pops up.

I think I’ve linked to all documentation on this topic in the posts above, including the API docs for ProfilerRecorders, which may help. The CPU Usage Profiler can help double-check what the relevant markers are named in the version you’re using. There’s also the question if you’re using .LastValue or .CurrentValue to check these and where in the Update loop you do that.

You may also use the Profiler Extensibility Features to add the recorded values to the profiler data stream and see them in context to see what’s going on.