Difference between revisions of "Profiling"

From GiderosMobile
 
(4 intermediate revisions by 2 users not shown)
Line 23: Line 23:
  
 
== Example ==
 
== Example ==
Let's see how profiling can help us, suppose you are running the following code:
+
Let's see how profiling can help us. Suppose you are running the following code:
<source lang="lua">
+
<syntaxhighlight lang="lua">
 
local function myFunction(a)
 
local function myFunction(a)
 
local function c(a) return math.cos(a*math.pi/180) end
 
local function c(a) return math.cos(a*math.pi/180) end
 
return c(a)+c(a+1)
 
return c(a)+c(a+1)
 
end
 
end
</source>
+
</syntaxhighlight>
  
 
and happen to use it very often. It is far from being optimized (on purpose, right) and turns out to be slow. How can we do better?
 
and happen to use it very often. It is far from being optimized (on purpose, right) and turns out to be slow. How can we do better?
  
 
Let's ask the profiler how does the code perform, say we want to run it 100,000 times:
 
Let's ask the profiler how does the code perform, say we want to run it 100,000 times:
<source lang="lua">
+
<syntaxhighlight lang="lua">
 
for i=1,100000 do myFunction(i) end
 
for i=1,100000 do myFunction(i) end
</source>
+
</syntaxhighlight>
  
 
This code outputs:
 
This code outputs:
<table>
 
<tr class="theader">
 
<th class="fnum">#</th>
 
<th class="ftime">Time</th>
 
<th class="fpct">Ratio</th>
 
<th class="fcount">Count</th>
 
<th class="fname">Function</th>
 
<th class="floc">Location</th>
 
</tr>
 
<tr class="current"><td><a id="f1">[1]</a></td><td>  423</td><td>  0%</td><td>    1</td><td>callFile</td><td>=[C] 00421900(callFile)</td></tr>
 
<tr class="callee"><td></td><td>  423</td><td>100%</td><td>    1</td><td><a href="#f2">Unknown</a></td><td>@main.lua:0:033FAC64</td></tr>
 
<tr class="sep"><td colspan=6>&nbsp;</td></tr>
 
<tr class="caller"><td></td><td>  423</td><td>100%</td><td>    1</td><td><a href="#f1">callFile</a></td><td>=[C] 00421900(callFile)</td></tr>
 
<tr class="current"><td><a id="f2">[2]</a></td><td>  423</td><td>  4%</td><td>    1</td><td>Unknown</td><td>@main.lua:0:033FAC64</td></tr>
 
<tr class="callee"><td></td><td>  405</td><td> 96%</td><td>100000</td><td><a href="#f3">myFunction</a></td><td>@main.lua:26:033FD87C</td></tr>
 
<tr class="sep"><td colspan=6>&nbsp;</td></tr>
 
<tr class="caller"><td></td><td>  405</td><td>100%</td><td>100000</td><td><a href="#f2">Unknown</a></td><td>@main.lua:0:033FAC64</td></tr>
 
<tr class="current"><td><a id="f3">[3]</a></td><td>  405</td><td> 35%</td><td>100000</td><td>myFunction</td><td>@main.lua:26:033FD87C</td></tr>
 
<tr class="callee"><td></td><td>  265</td><td> 65%</td><td>200000</td><td><a href="#f4">c</a></td><td>@main.lua:27:033FC328</td></tr>
 
<tr class="sep"><td colspan=6>&nbsp;</td></tr>
 
<tr class="caller"><td></td><td>  265</td><td>100%</td><td>200000</td><td><a href="#f3">myFunction</a></td><td>@main.lua:26:033FD87C</td></tr>
 
<tr class="current"><td><a id="f4">[4]</a></td><td>  265</td><td> 60%</td><td>200000</td><td>c</td><td>@main.lua:27:033FC328</td></tr>
 
<tr class="callee"><td></td><td>  107</td><td> 40%</td><td>200000</td><td><a href="#f5">cos</a></td><td>=[C] 6E416FE0(cos)</td></tr>
 
<tr class="sep"><td colspan=6>&nbsp;</td></tr>
 
<tr class="caller"><td></td><td>  107</td><td>100%</td><td>200000</td><td><a href="#f4">c</a></td><td>@main.lua:27:033FC328</td></tr>
 
<tr class="current"><td><a id="f5">[5]</a></td><td>  107</td><td>100%</td><td>200000</td><td>cos</td><td>=[C] 6E416FE0(cos)</td></tr>
 
<tr class="sep"><td colspan=6>&nbsp;</td></tr>
 
<tr class="current"><td><a id="f6">[6]</a></td><td>    2</td><td>100%</td><td>  313</td><td>gideros_enterFrame</td><td>=[C] 00423050(gideros_enterFrame)</td></tr>
 
<tr class="sep"><td colspan=6>&nbsp;</td></tr>
 
<tr class="current"><td><a id="f7">[7]</a></td><td>    0</td><td>100%</td><td>    1</td><td>broadcastEvent</td><td>=[C] 00423340(broadcastEvent)</td></tr>
 
<tr class="sep"><td colspan=6>&nbsp;</td></tr>
 
</table>
 
  
 +
[[File:profiling01.png]]
  
 
This is a list of all functions ran by the code sorted by CPU usage (highest first). The first chunk is about a function called ''callFile''. It is an internal Gideros Function which loads each lua file. In our case it was used to launch main.lua, which corresponds to block [2].
 
This is a list of all functions ran by the code sorted by CPU usage (highest first). The first chunk is about a function called ''callFile''. It is an internal Gideros Function which loads each lua file. In our case it was used to launch main.lua, which corresponds to block [2].
  
 
Let's focus on our function ''myFunction'', we can see it is covered by block [3]:
 
Let's focus on our function ''myFunction'', we can see it is covered by block [3]:
<table>
 
<tr class="theader">
 
<th class="fnum">#</th>
 
<th class="ftime">Time</th>
 
<th class="fpct">Ratio</th>
 
<th class="fcount">Count</th>
 
<th class="fname">Function</th>
 
<th class="floc">Location</th>
 
</tr>
 
<tr class="caller"><td></td><td>  405</td><td>100%</td><td>100000</td><td><a href="#f2">Unknown</a></td><td>@main.lua:0:033FAC64</td></tr>
 
<tr class="current"><td><a id="f3">[3]</a></td><td>  405</td><td> 35%</td><td>100000</td><td>myFunction</td><td>@main.lua:26:033FD87C</td></tr>
 
<tr class="callee"><td></td><td>  265</td><td> 65%</td><td>200000</td><td><a href="#f4">c</a></td><td>@main.lua:27:033FC328</td></tr>
 
</table>
 
  
 +
[[File:profiling01B.png]]
  
So the function ''myFunction'' took, as expected, most of the processing time. Figures tell us that it was called 100,000 times and consumed 405ms on CPU. We also learn that it was called from an unnamed function located at main.lua:0, which is the toplevel lua code of main.lua file, and that all the time (100%) spent in myFunction was due to being called by main.lua.
+
So the function ''myFunction'' took, as expected, most of the processing time. Figures tell us that it was called 100,000 times and consumed 349ms on CPU. We also learn that it was called from an unnamed function located at main.lua:0, which is the toplevel lua code of main.lua file, and that all the time (100%) spent in myFunction was due to being called by main.lua.
  
More interestingly, we discover that 65% of the time (265ms) was spent in calls to function ''c'' located at main.lua:27, and that c was called 200,000 times, twice per call.
+
More interestingly, we discover that 65% of the time (228ms) was spent in calls to function ''c'' located at line main.lua:2, and that c was called 200,000 times, twice per call.
  
The next chunk is about function ''c'': 40% of the time of ''c'' was spent in math.cos(), and 60% in the function itself.
+
The next chunk is about function ''c'': 41% of the time of ''c'' was spent in math.cos(), and 59% in the function itself.
  
 
We know that calling a function is expensive, and that ''c'' function is rather simple. Lets try to inline it:
 
We know that calling a function is expensive, and that ''c'' function is rather simple. Lets try to inline it:
<source lang="lua">
+
<syntaxhighlight lang="lua">
 
local function myFunction(a)
 
local function myFunction(a)
 
return math.cos(a*math.pi/180)+math.cos((a+1)*math.pi/180)
 
return math.cos(a*math.pi/180)+math.cos((a+1)*math.pi/180)
 
end
 
end
</source>
+
</syntaxhighlight>
  
 
Now profiler report looks like this: (truncated)
 
Now profiler report looks like this: (truncated)
<table>
 
<tr class="theader">
 
<th class="fnum">#</th>
 
<th class="ftime">Time</th>
 
<th class="fpct">Ratio</th>
 
<th class="fcount">Count</th>
 
<th class="fname">Function</th>
 
<th class="floc">Location</th>
 
</tr>
 
<tr class="caller"><td></td><td>    65</td><td>100%</td><td>100000</td><td><a href="#f2">Unknown</a></td><td>@main.lua:0:033FC4FC</td></tr>
 
<tr class="current"><td><a id="f3">[3]</a></td><td>    65</td><td> 73%</td><td>100000</td><td>myFunction</td><td>@main.lua:26:033FB670</td></tr>
 
<tr class="callee"><td></td><td>    17</td><td> 27%</td><td>200000</td><td><a href="#f4">cos</a></td><td>=[C] 6E416FE0(cos)</td></tr>
 
<tr class="sep"><td colspan=6>&nbsp;</td></tr>
 
<tr class="caller"><td></td><td>    17</td><td>100%</td><td>200000</td><td><a href="#f3">myFunction</a></td><td>@main.lua:26:033FB670</td></tr>
 
<tr class="current"><td><a id="f4">[4]</a></td><td>    17</td><td>100%</td><td>200000</td><td>cos</td><td>=[C] 6E416FE0(cos)</td></tr>
 
</table>
 
  
 +
[[File:profiling02.png]]
  
''myFunction'' is already faster: 65ms now where we had 405ms before.
+
''myFunction'' is already faster: 56ms now where we had 349ms before.
  
 
We still call math.cos two times. Lets make it (and math.pi) local.
 
We still call math.cos two times. Lets make it (and math.pi) local.
<source lang="lua">
+
<syntaxhighlight lang="lua">
 
local function myFunction(a)
 
local function myFunction(a)
 
local cos=math.cos
 
local cos=math.cos
Line 132: Line 74:
 
return cos(a*pi/180)+cos((a+1)*pi/180)
 
return cos(a*pi/180)+cos((a+1)*pi/180)
 
end
 
end
</source>
+
</syntaxhighlight>
  
 
Now the profiler report:
 
Now the profiler report:
<table>
 
<tr class="theader">
 
<th class="fnum">#</th>
 
<th class="ftime">Time</th>
 
<th class="fpct">Ratio</th>
 
<th class="fcount">Count</th>
 
<th class="fname">Function</th>
 
<th class="floc">Location</th>
 
</tr>
 
<tr class="caller"><td></td><td>    60</td><td>100%</td><td>100000</td><td><a href="#f2">Unknown</a></td><td>@main.lua:0:033FAC64</td></tr>
 
<tr class="current"><td><a id="f3">[3]</a></td><td>    60</td><td> 71%</td><td>100000</td><td>myFunction</td><td>@main.lua:26:033FD1E8</td></tr>
 
<tr class="callee"><td></td><td>    17</td><td> 29%</td><td>200000</td><td><a href="#f4">cos</a></td><td>=[C] 6E416FE0(cos)</td></tr>
 
</table>
 
  
 +
[[File:profiling03.png]]
  
 
We saved time in ''myFunction'', while ''cos()'' took the same time.
 
We saved time in ''myFunction'', while ''cos()'' took the same time.
  
 
What if we use Gideros deg to rad operator instead of math.pi and 180 constant?
 
What if we use Gideros deg to rad operator instead of math.pi and 180 constant?
<source lang="lua">
+
<syntaxhighlight lang="lua">
 
local function myFunction(a)
 
local function myFunction(a)
 
local cos=math.cos
 
local cos=math.cos
 
return cos(^<a)+cos(^<(a+1))
 
return cos(^<a)+cos(^<(a+1))
 
end
 
end
</source>
+
</syntaxhighlight>
  
 
Profiler report:
 
Profiler report:
<table>
 
<tr class="theader">
 
<th class="fnum">#</th>
 
<th class="ftime">Time</th>
 
<th class="fpct">Ratio</th>
 
<th class="fcount">Count</th>
 
<th class="fname">Function</th>
 
<th class="floc">Location</th>
 
</tr>
 
<tr class="caller"><td></td><td>    57</td><td>100%</td><td>100000</td><td><a href="#f2">Unknown</a></td><td>@main.lua:0:033FC4FC</td></tr>
 
<tr class="current"><td><a id="f3">[3]</a></td><td>    57</td><td> 69%</td><td>100000</td><td>myFunction</td><td>@main.lua:26:033FB9DC</td></tr>
 
<tr class="callee"><td></td><td>    17</td><td> 31%</td><td>200000</td><td><a href="#f4">cos</a></td><td>=[C] 6E416FE0(cos)</td></tr>
 
</table>
 
  
 +
[[File:profiling04.png]]
  
 
We saved a few more precious milliseconds!
 
We saved a few more precious milliseconds!
Line 185: Line 103:
  
 
'''PREV.''': [[File system]]<br/>
 
'''PREV.''': [[File system]]<br/>
'''NEXT''': [[Hardware and OS]]<br/>
+
'''NEXT''': [[Hardware and OS]]
 +
 
 +
 
 +
{{GIDEROS IMPORTANT LINKS}}

Latest revision as of 03:30, 6 January 2024

The Ultimate Guide to Gideros Studio

Profiling

Gideros comes with an integrated native Lua profiler.

For those who don't know what is a code profiler, it is a tool that measures code effectiveness and outputs statistics about the CPU usage: number of times each function was called, how much time it took to execute, where it was called from.

Gideros provides two means of enabling profiling:

  • by launching a profiling session directly through 'Profile' menu item or toolbar icon from Gideros Studio
  • by calling Core.profiler* API from Lua

In the former case, Gideros Studio will display the profiling results when the stop button is hit in Gideros Studio toolbar. In the latter, you have to handle profiling data collection and display by yourself.

Note that even if you started profiling through Gideros Studio, you can still use Core.profiler* API within your code.

Available Gideros profiling API:

  • Core.profilerStart(), which instructs Gideros to 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

Example

Let's see how profiling can help us. Suppose you are running the following code:

local function myFunction(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. How can we do better?

Let's ask the profiler how does the code perform, say we want to run it 100,000 times:

for i=1,100000 do myFunction(i) end

This code outputs:

Profiling01.png

This is a list of all functions ran by the code sorted by CPU usage (highest first). The first chunk is about a function called callFile. It is an internal Gideros Function which loads each lua file. In our case it was used to launch main.lua, which corresponds to block [2].

Let's focus on our function myFunction, we can see it is covered by block [3]:

Profiling01B.png

So the function myFunction took, as expected, most of the processing time. Figures tell us that it was called 100,000 times and consumed 349ms on CPU. We also learn that it was called from an unnamed function located at main.lua:0, which is the toplevel lua code of main.lua file, and that all the time (100%) spent in myFunction was due to being called by main.lua.

More interestingly, we discover that 65% of the time (228ms) was spent in calls to function c located at line main.lua:2, and that c was called 200,000 times, twice per call.

The next chunk is about function c: 41% of the time of c was spent in math.cos(), and 59% in the function itself.

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

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

Now profiler report looks like this: (truncated)

Profiling02.png

myFunction is already faster: 56ms now where we had 349ms before.

We still call math.cos two times. Lets make it (and math.pi) local.

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

Now the profiler report:

Profiling03.png

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

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

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

Profiler report:

Profiling04.png

We saved a few more precious milliseconds!

Conclusion

As you can see, the profiler is a useful tool to spot CPU bottlenecks in your app.

Sometimes a few minor changes in the code can make a big difference. In general, avoid table access, avoid function calls, avoid duplicate computations.


PREV.: File system
NEXT: Hardware and OS