Is the profiler cheating?

I was doing some benchmarks on pure ECS, and I was impressed by what is seemed to be a huge performance gain until I saw this:



At first glance it seems the game is running around 200 frames per second, however it is actually running at less than 15.

 

Can you expand tree to see what you got there? Is there any synchornisation?


Also, can you switch to timeline like on my screenshot, to see threads?

 

Probably waiting for job. If possible you might post the code here so we could make sense of it.

 

That what I expect. Time is often takes into consideration waiting period between jobs.

 

Ignore the actual ms times in Profiler. It is not an accurate frame time. The profiler itself adds overhead. You will likely see this when you switch from regular profiling to deep profiling, usually the ms time goes up noticably.

When you start optimizing performance and have 100ms per frame time and you keep optimizing until you get to 30 ms frametime then you know you‘ve made a significant improvement. But in terms of actual fps you will most likely not see an exact jump from say 10 fps to 30 fps. You have to measure actual fps in a build using an fps counter (built-in or fraps or Nvidia overlay). Use the ms time only as a relative indicator to where you started at when you begin profiling.

 

According to the tinted UI, you seem to profile the game running in the editor. Unity Technologies recommend to profile a build on the target platform instead.

Spoiler: Unite Seoul 2018 - When optimization goes wrong

 

While this is true in general, personally I wouldn't be advising everyone, to build game just to check, how script / system performs after some changes.
Editor profiler is good for having reference point, if there is any progress on the optimization. Or if something goes wrong. Even if there is significant check overhead.

But I would say, if fps drops significantly and no other way to improve, or prove what is wrong, then I would go for in build performance check.

 

The Unite talk I linked to explains that often people seem to hunt performance and memory problems that actually do not exist, because they profile the game running in the editor, rather than a build.

I would at least profile a build before I start optimizing and afterwards.

 

Yep, you are definitely right.
My point was, maybe not specified precisely, that is just no need to build ever time, when script is changed.

 

I don't think that's the case as I have only one system, however I'm posting the timeline, for you to see:

Here it is... But I want to make clear two things before you read it: 1) I wrote this code for benchmark purposes only, with the only intention to push the CPU as hard as possible, so don't try to make sense out of it. 2) I'm just starting to explore the ECS paradigm, so DO expect to see crazy things.

Code (CSharp):

1. [BurstCompile]
2.    public class AISystemPure : JobComponentSystem {
3.  
4.  
5.    
6.       public struct AIJob : IJobProcessComponentData<AIParam> {
7.      
8.          public void Execute(ref AIParam driver) {
9.             for(int i = 0;i<10000;i++) {
10.                driver.WayPoint = driver.WayRight;
11.                driver.WayRight = driver.WayUp;
12.                driver.WayForward = driver.WayPoint;
13.                driver.WayDistance = (driver.WayPoint-driver.WayRight).magnitude;
14.                driver.WayDistance = Vector3.Dot(driver.WayForward,driver.WayRight);
15.                Vector3 p = Vector3.ProjectOnPlane(driver.WayForward,driver.WayUp);
16.                driver.WayPoint = p.normalized;
17.             }
18.          }
19.  
20.       }
21.  
22.  
23.       protected override JobHandle OnUpdate(JobHandle deps) {
24.      
25.          AIJob job = new AIJob();
26.          return job.Schedule(this,deps);
27.       }
28.  
29.  
30.  
31.    }

I think you all are missing the point here. What'm trying to point out is the fact that the graphic information does not math the numeric data. The numeric data is accurate and it matches what I see on the Entity debugger, but it has absolutely nothing to do with what I see on the graph!

Totally agree.

 

This is not how you should execute IJob in pure ECS.

Where you got that example reference from, if I may ask?
Have you seen Two Stick sample, to see how Jobs are executed?

Because 10k iterations is really nothing for ECS.

Do you use class by any chance in the job?
And vector should be technically float3 for best performance.

 

Yes I know, but like I said, this just a benchmark to test a extreme case (that may never happen in real life), I just want to see how far I can push the boundaries without breaking the system. The intention of the for loop is not to process data but just to simulate a extremely large set of instructions, I wouldn't write 10,000 times Vector3.ProjectOnPlane, etc. that's why I'm using a for loop. People usually tests system performance with a large number of entities doing very little processing, I'm trying to see what happens if you have a small number of entities with an extremelly heavy process.

But again the original intention of this post was to point out a very specific mismatch on the profiler, not to argue about performance.

 

Fair enough.

I think reason why you you see on the first graph, almost no overhead for your script, is because job is running on a thread. While the main graph is showing things going on main thread. It may be the case, that profile didn't pick it up. This is my assumption. While timing appears to be more correct, in both cases.

That is why you got secondary worker threading profiler on the timeline.

 

Sound reasonable as the profiler was designed before the job system. Is not a major issue, however I think the graph should match what you see in the numbers by all means.

 

Well, not really. Because you game is still responsive, while thread doing own work, for whatever long it needs too.
Because one thread is running, doesn't mean you get low FPS. And that what is the graph indicating. Time corresponding to FPS.

So you still can have 30, 60,100 etc. FPS, irrespective what threads are doing.

 

Yes, you are right, it is impossible to have an exact match because you have two incompatible ways of measuring time, however all the information to make a rough estimated is already on the timeline. If you see closely the second image I posted, the profiler knows the worker thread spent 93.84 ms!, so it shouldn't be that hard to reflect it on the graph.

 

I know what you are saying.
But in my opinion that would be more confusing than need to be. This would require additional graph filters, which are not there.
That is why you have threading, which displays clearly what you need on the timeline.

 

You are not running burst on your example. Move the burst attribute to the job, not on the system.

 

I think OP is aware about this by now.
But as pointed out, that is not the main goal of this thread. Is the profiler itself.

 

Case 1080435 (hierarchy)

I'm not sure if the Timeline is a bug or not, so I didn't file a bug report for that.

 

Thanks for the update!