How to know what part of a job takes the longest time ?

[glossy knot]

Hello!
I'm making a pathfinding job and I would like to optimize it but for that, I would need to know what part of the algorithm takes the longest time.
But when I use the profiler, I only see the time the job takes without any other details.
Ideally I would like to see how much time each function took (but they are called thousands of times in one single job so I'm not sure if it's possible).

Is there a way to do that? I've just started to use the profiler so maybe I'm missing something ?
Or is there a way to measure very small amounts of time (probably a few µs for a single execution of a function) precisely with C# ?

Also the one I suspect to take the longest time is one that modifies an array so I can't make it loop thousands of times to see precisely how much time it takes 😦

[devout hearth]

You can't. Unless you can split logic between multiple jobs

or by benchmarking functions in isolation

[glossy knot]

Oh ok, thank you 😢

And would it be reasonable to make a job for a few µs ?

Or would creating the job and running it take longer?

[devout hearth]

well, I doubt it's few nanoseconds

just split job into multiple parts

[glossy knot]

No, micro seconds

[devout hearth]

this at least will narrow down responsible parts

to less candidates

[glossy knot]

Yes but the problem is it's a recursive algorithm so it calls every function thousands of times 😭

Like I have a big while loop that calls all the functions every time

(Ok now that I'm thinking about it I'm not sure about the word recursive but still 😅 )

Iterative maybe

Oh wow I tried using Execute() directly instead of Run() but it froze the game, there was an error that I couldn't read (but it was talking about memory) and Unity was taking 10 Gb of memory 🥲

[modern granite]

If you use a sampling profiler like Superluminal you can see the calls under the job Execute.

You can also enable deep profiling in the Unity profile and see callstacks inside your jobs to get a better idea of where time is going inside of a job. But do note that deep profiling will slow things down a bit, so you're looking at relative differences between function calls

[glossy knot]

Thank you, deep profiling and call stacks work! 🙂
I have to press pause very quickly though otherwise the memory gets filled and everything is frozen 😅
Is there a way to only record a few frames?

I'm guessing it's the data recorded by the profiler that fills the memory?

It's weird, I was able to see all my functions before but it doesn't work anymore 🤔

Even with call stack and deep profiler enabled

Ahh no it works when I do Execute() and not Run(), I had left that the first time I tried today 😅

[devout hearth]

because when you call Execute you quite literally just call your own mono code

while Run calls burst compiled function pointer

[glossy knot]

Ooh ok but then I can't really know if it's the same with Burst

[devout hearth]

it's definitely not

[glossy knot]

That's annoying but the function I thought takes 70% of the player update so I guess I should optimise it no matter what 😅

[glossy hamlet]

you can use https://github.com/StrangeLoopGames/NativeTime to time sections inside burst compiled jobs but you will need to get those values back out and display them

[glossy knot]

Interesting, I'll try this, thank you!

[glossy knot]

That works great! 🙂
It slows the job down a little bit but not too too much so it's fine 🙂

Hmm actually when I add it in the smallest function I have, it doubles the time 😢
But I don't know if that time is included inside the TimeSpan or not.

If I do :

ValueStopwatch watch = ValueStopwatch.StartNew();

// Some code

time += watch.ElapsedTicks.Ticks;

Do you think some of the overhead of measuring the time will be seen it the time I measure ?

[glossy knot]

I did some testing on a very small function :
Everytime the function is called, the time it took to execute is added to a time variable (the function is very small but is called thousands of times).
Like this, the total time measured is about 0.3 ms.
But if I add a loop in the function to make it execute 1000 times (but without executing the ValueStopwatch functions 1000 times), it only takes 50 ms.
So my guess is that in the 0.3 ms, only 1/6 was the actual function's execution time 😦

I added a count to see the actual time per function execution and it looks like it's actually 10 ns so the time added by measuring the time would be about 50 ns 🙂

[devout hearth]

assuming it's using locks/interlocks that value will heavily vary based of how often it gets called between threads

[glossy knot]

Oh but I wasn't multithreading it yet, I was using Run()

[devout hearth]

but time counting happens on other thread still

[glossy knot]

Does that change something?
I'm not using any lock or anything like that, am I doing something wrong?

Plus, does Run run the code in another thread?
Doesn't it run it in the main thread if I call it from the main thread?

[devout hearth]

stopwatch does.
It doesn't change anything, just should be taken into account that time profiling adds can heavily vary because of that

[devout hearth]

It does, but how do you count time then?

[glossy knot]

Oh ok, I had no idea how the time is counted 😅

[glossy hamlet]

ValueStopwatch wraps QueryPerformanceCounter on windows so it's just about as fast as you can get with the overhead, you can read more about it at https://learn.microsoft.com/en-us/windows/win32/sysinfo/acquiring-high-resolution-time-stamps

But if your job is taking less than a microsecond then you're getting into territory where the overhead of running a job is going to be more than the job itself