Search Issue Tracker

Active

Under Consideration for 3.0.X

Votes

0

Found in [Package]

3.0.3

Issue ID

BUTFP-24

Regression

No

Can't obtain timing data of C# job using ProfilerMarkers() function

Package: Performance Test Framework

-

We can't obtain timing data of C# jobs using the {{Measure.ProfilerMarkers()}} function in a {{[Performance]}} test. See [this slack thread|https://unity.slack.com/archives/CHVTMBEF5/p1715012043191819] for context and discussion of this issue.

*Steps to reproduce:*
Run any simulation that contains a C# job and try to obtain accumulated frame time of said job using the ProfilerMarker() in a [Performance] test.
Example steps:
# Clone https://github.cds.internal.unity3d.com/unity/dots and checkout branch master
# With VPN access, in the root folder run the command {{.\project-launcher.cmd PhysicsSamples}}. This will download the correct editor version if required (hence the VPN access).
# In the PhysicsSamples project, add the following test class to the file PhysicsPerformanceTests.cs before the class {{UnityPhysics_PerformanceTest_Parallel}}:
{code}
class ColliderParadePerformanceTest : UnityPhysicsSamplesTest
{
[SetUp]
public void SetUp()
{
ConfigureSimulation(World.DefaultGameObjectInjectionWorld, SimulationType.UnityPhysics);
}

[UnityTest, Performance]
[Timeout(10000000)]
public override IEnumerator LoadScenes([Values("Collider Parade - Basic")] string scenePath)
{
SceneManager.LoadScene(scenePath);

var sampleGroups = new[]
{
// This sample group will return non-zero timing data which is expected.
new SampleGroup("Default World Unity.Entities.FixedStepSimulationSystemGroup"),
// This sample group will return zero timing data which is unexpected.
new SampleGroup("Broadphase:StaticVsDynamicFindOverlappingPairsJob (Burst)"),
};

yield return Measure.Frames()
.ProfilerMarkers(sampleGroups)
.WarmupCount(10)
.MeasurementCount(360)
.Run();
}
}
{code}
# Make sure that Burst is enabled (Jobs -> Burst -> Enable Compilation) and that the compilation has finished (see progress bar in lower right of editor).
# In the Test Runner, run the performance test "ColliderParadePerformanceTest" and observe that once the test has completed, there will be only zero timing data collected for the sample group for the C# job with name "Broadphase:StaticVsDynamicFindOverlappingPairsJob (Burst)".

\\
*Actual results:* 
The data returned by the performance test for the C# job profiler markers read zero for every frame. See below.
!image-2024-05-14-21-26-19-832.png|thumbnail!
*Expected results:* 
We should get non-zero timing data for every frame in which the job is run.

\\
*Reproducible with versions:* 
* com.unity.test-framework.performance: 3.0.3
* unity/dots master branch: sha1 e514cc30aba892b1ae83c225a3aebe2185b3d5ac
* Unity Editor: 6000.0.0b15-3053e3451d4f

*Not reproducible with versions:* 
N/A
*Can’t test with versions:* 
N/A

\\
*Tested on (OS):* 
Windows 10

\\
*Notes:*
The timing data is available as I was able to show by adding the following MonoBehavior script to the scene "ColliderParade - Basic.unity".
{code}
using Unity.Profiling;
using UnityEditor.Profiling;
using UnityEditorInternal;
using UnityEngine;
using UnityEngine.Profiling;

namespace Tests.Performance.TreeLifetimePerformanceTest
{
public class SomeMonoBehavior : MonoBehaviour
{
ProfilerRecorder recorder;
Recorder behaviourUpdateRecorder;
Recorder behaviourUpdateRecorder2;
void Start()
{
behaviourUpdateRecorder = Recorder.Get("Broadphase:StaticVsDynamicFindOverlappingPairsJob (Burst)");
behaviourUpdateRecorder.enabled = true;

behaviourUpdateRecorder2 = Recorder.Get("Default World Unity.Entities.FixedStepSimulationSystemGroup");
behaviourUpdateRecorder2.enabled = true;

recorder = ProfilerRecorder.StartNew(ProfilerCategory.Scripts, "Broadphase:StaticVsDynamicFindOverlappingPairsJob (Burst)");
}

void Update()
{
// Does not work. Time is zero.
if (behaviourUpdateRecorder.isValid)
Debug.Log("BehaviourUpdate time: " + behaviourUpdateRecorder.elapsedNanoseconds);

// Does work. Time is non-zero.
if (behaviourUpdateRecorder2.isValid)
Debug.Log("BehaviourUpdate2 time: " + behaviourUpdateRecorder2.elapsedNanoseconds);

// Does not work. Time is zero.
Debug.Log("ProfilerRecorder time: " + recorder.CurrentValue);

// Low-level method works. Time is non-zero.
var totalTime = 0.0f;
for (int j = 0;; ++j)
{
using RawFrameDataView frame = ProfilerDriver.GetRawFrameDataView(Time.frameCount, j);
if (!frame.valid)
break;

var markerId = frame.GetMarkerId("Broadphase:StaticVsDynamicFindOverlappingPairsJob (Burst)");
int sampleCount = frame.sampleCount;
for (int i = 0; i < sampleCount; ++i)
{
if (markerId != frame.GetSampleMarkerId(i))
continue;

var time = frame.GetSampleTimeMs(i);
totalTime += time;
}
}
Debug.Log("FrameData time: " + totalTime);
}
}
}
{code}
In the code above, the job timing data can only be obtained by using the low level profiler API: {{RawFrameDataView frame = ProfilerDriver.GetRawFrameDataView(Time.frameCount, j);}}
All other attempts to obtain the data, both using the ProfilerRecorder and the legacy Recorder fail.
See here for successful retrieval of the results through the above mentioned low level API:
!image-2024-05-14-21-39-41-013.png|thumbnail!

We can see that profiler markers are created for such jobs in the engine [here|https://github.cds.internal.unity3d.com/unity/unity/blob/trunk/Runtime/Jobs/JobReflectionData.cpp#L690]:
{code}
#if ENABLE_PROFILER
char* jobName;
size_t jobNameLen = strlen(data->async.jobName);
ALLOC_TEMP_AUTO(jobName, jobNameLen + std::max(strlen(kBurstPostfix), strlen(kCombinePostfix)) + 1);
strcpy(jobName, data->async.jobName);
data->async.profilerInfoManaged = GetOrCreateProfilerMarker(jobName, profiling::kProfilerManagedJobs);

strcpy(jobName + jobNameLen, kBurstPostfix);
data->async.profilerInfoBurst = GetOrCreateProfilerMarker(jobName, profiling::kProfilerBurstJobs);

strcpy(jobName + jobNameLen, kCombinePostfix);
data->async.profilerInfoCombineJob = GetOrCreateProfilerMarker(jobName, profiling::kProfilerManagedJobs);
#endif
{code}

Add comment

Log in to post comment

All about bugs

View bugs we have successfully reproduced, and vote for the bugs you want to see fixed most urgently.