* * * * *

               “Nobody Expects the Surprising Profile Results!”

It still surprises me that the results of profiling can be so surprising.

Today I profiled Lua code as Lua [1]. It was less work than expected [2] and
all it took was about 30 lines of Lua code. For now, I'm just recording the
file name, function name (if available—not all Lua functions have names) and
the line number as that's all that's really needed.

But as I was writing the code to profile the code, I wasn't expecting any
real results from profiling “Project: Sippy-Cup [3].” The code is really
just:

 1. get packet
 2. parse packet
 3. validate SIP (Session Initiaion Protocol) message
 4. acknowledge SIP message
 5. get relevent data from SIP message
 6. query “Project: Lumbergh [4]” (business logic)
 7. wait for results
 8. send results in SIP message
 9. wait for SIP acknowledgement
10. done

I was expecting a fairly uniform profile result, and if pressed, maybe a blip
for awaiting results from “Project: Lumbergh” as that could take a bit. What
I did not expect was this:

Table: Surprising Profile Results
count   file/function/line
------------------------------
21755   @third_party/LPeg-Parsers/ip-text.lua::44
6000    @XXXXX­XXXXX­XXXXX­XXXXX­XXXXX­X:send_query:339
2409    @XXXXX­XXXXX­XXXXX­XXXXX:XXXXX­XXXX:128

After that, the results tend to flatten out. And yes, the send_query() makes
sense, but ip-text.lua [5]? Three times more than the #2 spot?

This line of code?

-----[ Lua ]-----
local n = tonumber(capture,16)
-----[ END OF LINE ]-----

That's the hot spot? Wait? I'm using IP (Internet Protocol version)v6 for the
regression test? When did that happen? Wait? I'm surprised by that as well?
What is going on here?

Okay, breathe.

Okay.

I decide to do another run, this time at a finer grain, about 1/10 the
previous profiling interval and see what happens.

Table: Finer Grained Surprising Profile Results
count   file/function/line
------------------------------
133186  @third_party/LPeg-Parsers/ip-text.lua::44
29683   @third_party/LPeg-Parsers/ip-text.lua::46
21910   @third_party/LPeg-Parsers/ip-text.lua::45
19749   @XXXXX­XXXXX­XXXXX­XXXXX­XXXXX­XX:XXXXX­XXXXX­XXX:279

And the results flatten out after that. So the hot spot of “Project: Sippy-
Cup” appears to be this bit of code:

-----[ Lua ]-----
local h16 = Cmt(HEXDIG^1,function(_,position,capture)
 local n = tonumber(capture,16)
 if n < 65536 then
   return position
 end
end)
-----[ END OF LINE ]-----

send_query() doesn't show up until the 26^TH spot, but since it's finer
grained, it does show up multiple times, just at different lines.

So … yeah.

I have to think on this.

[1] gopher://gopher.conman.org/0Phlog:2019/08/20.1
[2] gopher://gopher.conman.org/0Phlog:2019/08/20.1
[3] gopher://gopher.conman.org/0Phlog:2014/03/05.1
[4] gopher://gopher.conman.org/0Phlog:2018/09/11.2
[5] https://github.com/spc476/LPeg-Parsers/blob/9ac0d6f338e1429c2e037bc510516b990576ac1d/ip-text.lua

Email author at [email protected]