Profiling code in 2017.8

hgy29

Gideros 2017.8 comes with an integrated native lua profiler.

For those who don't know what is a code profiler, it is a tool that measure effectiveness of the code and outputs statistics about the CPU usage: number of times each function was called, how much time it took to execute, and where was it called from. Gideros nows provide four functions to manage a profiling session:
- Core.profilerStart(), which instructs gideros start collecting profiling data
- Core.profilerStop(), which pause collecting
- Core.profilerReset(), which clears collected data
- Core.profilerReport(), which returns a table containing collected profiling data

To ease report generation, I've made a small lua file which convert the collected data into a more readable log. My profiler has just two functions: Profiler.start(): start profiling, Profiler.stop(): stop profiling and outputs data on console.

Ok, but what is it for ?

So suppose you are running the following code:

local function myFunction1(a) local function c(a) return math.cos(a*math.pi/180) end return c(a)+c(a+1) end

and happen to use it very often. It is far from being optimized (on purpose, right) and turns out to be slow, but how can we do better ?

Lets ask the profiler how does it run, say we want to run it 1000000 times:

local function profile(myFunction) Profiler.start() for i=1,1000000 do myFunction(i) end Profiler.stop() end   profile(myFunction1)

This code outputs:

< [ 6] 3768 100% 1000000 <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:22 = [ 1] 3768 36% 1000000 myFunction <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:1 > [ 2] 2424 64% 2000000 c <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:2 -------------------------------- < [ 1] 2424 100% 2000000 myFunction <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:1 = [ 2] 2424 63% 2000000 c <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:2 > [ 3] 892 37% 2000000 cos =[C] 6E416930 -------------------------------- < [ 2] 892 100% 2000000 c <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:2 = [ 3] 892 100% 2000000 cos =[C] 6E416930 -------------------------------- = [ 4] 0 -1% 0 =[C] 00456FA0 -------------------------------- = [ 5] 0 -1% 0 stop <a href="https://forum.gideros.rocks/profile/profiler" rel="nofollow">@profiler</a>.lua:7 -------------------------------- = [ 6] 0 -1% 0 <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:22 > [ 1] 3768 1% 1000000 myFunction <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:1 -------------------------------- = [ 7] 0 -1% 0 <a href="https://forum.gideros.rocks/profile/profiler" rel="nofollow">@profiler</a>.lua:2 -------------------------------- = [ 8] 0 -1% 0 profilerStop =[C] 004536A0 --------------------------------

This is a list of all functions ran by the code sorted by CPU usage (highest first). The first chunk is:

< [ 6] 3768 100% 1000000 <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:22 (This is the function that called this one) = [ 1] 3768 36% 1000000 myFunction <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:1 (This is the considered function) > [ 2] 2424 64% 2000000 c <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:2 (This is the function that was called by this function)

So the function 'myFunction' took most of the time. Figures tell us that it was called 1000000 times and consumed 3768ms on CPU. We also learn that it was called from function [6], located at main.lua:22, and that all the time (100%) spent in myFunction was due to being called by main.lua:22.
More interesting, we discover that 64% of the time (2424ms) was spent in calls to function [2], named 'c' and located at main.lua:2, and that c was called 2000000 times (twice per call).

The second chunk, about function [2], that is c@main.lua:2 shows us that 37% of the time was spent in math.cos(), and 63% in the function itself.

We now that calling a function is expensive, and that 'c' function is rather simple. Lets try to inline it:

local function myFunction2(a) return math.cos(a*math.pi/180)+math.cos((a+1)*math.pi/180) end

Now profiler report looks like this: (truncated)

< [ 5] 912 100% 1000000 <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:22 = [ 1] 912 76% 1000000 myFunction <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:6 > [ 2] 215 24% 2000000 cos =[C] 6E416930 -------------------------------- < [ 1] 215 100% 2000000 myFunction <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:6 = [ 2] 215 100% 2000000 cos =[C] 6E416930

myFunction is already faster: 912ms now where we had 3768ms before.
We still call math.cos two times. Lets make it (and math.pi) local.

local function myFunction3(a) local cos=math.cos local pi=math.pi return cos(a*pi/180)+cos((a+1)*pi/180) end

and profiler report:

< [ 6] 798 100% 1000000 <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:22 = [ 1] 798 73% 1000000 myFunction <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:10 > [ 2] 216 27% 2000000 cos =[C] 6E416930

We saved time in myFunction, while cos() took the same time.

What if we use new gideros deg to rad operator instead of math.pi and 180 constant ?

local function myFunction4(a) local cos=math.cos return cos(^<a)+cos(^<(a+1)) end

and profiler report:

< [ 5] 741 100% 1000000 <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:22 = [ 1] 741 71% 1000000 myFunction <a href="https://forum.gideros.rocks/profile/main" rel="nofollow">@main</a>.lua:16 > [ 2] 216 29% 2000000 cos =[C] 6E416930

We saved a few more precious milliseconds!

As you can see, the profiler is an useful tool to spot CPU bottlenecks in your app, and some times a few minor changes in the code can make big differences: avoid table access, avoid function calls, avoid duplicate computations.

keszegh

this all sounds quite useful.
"I've made a small lua file " - could you share this with us too?

hgy29

@keszegh, yes of course. I forgot to attach it to my original post, fixed now.

snooks

This is great, I was going to ask about profiling options a few days ago and here it is! Thanks!