The Boston Diaries

The ongoing saga of a programmer who doesn't live in Boston, nor does he even like Boston, but yet named his weblog/journal “The Boston Diaries.”

Go figure.

Wednesday, August 21, 2019

“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. It was less work than expected 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.” The code is really just:

  1. get packet
  2. parse packet
  3. validate SIP message
  4. acknowledge SIP message
  5. get relevent data from SIP message
  6. query “Project: Lumbergh” (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:

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? Three times more than the #2 spot?

This line of code?

local n = tonumber(capture,16)

That's the hot spot? Wait? I'm using IPv6 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.

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:

local h16 = Cmt(HEXDIG^1,function(_,position,capture)
  local n = tonumber(capture,16)
  if n < 65536 then
    return position
  end
end)

send_query() doesn't show up until the 26TH 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.


Done with the profiling for now

After some more profiling work I've come to the conclusion that yes, the hot spot is in ip-text.lua, and that after that function, it's quite flat otherwise. The difference between ip-text.lua and the number two spot isn't quite as bad as I initially thought, although it took some post-processing to lump all the function calls together to determine that (required because Lua can't always know the “name” of a function, but with the line numbers they can be reconciled). It's only called about twice as much as the next most used function instead of the nearly 4½ times it appeared earlier.

As far as profiling “Project: Sippy-Cup” is concerned, I think I'm about as far as I can go at this time. I did improve the performance with some minor code changes and any more improvement will take significant resources. So I'm calling it good enough for now.

Obligatory Picture

[It's the most wonderful time of the year!]

Obligatory Links

Obligatory Miscellaneous

You have my permission to link freely to any entry here. Go ahead, I won't bite. I promise.

The dates are the permanent links to that day's entries (or entry, if there is only one entry). The titles are the permanent links to that entry only. The format for the links are simple: Start with the base link for this site: http://boston.conman.org/, then add the date you are interested in, say 2000/08/01, so that would make the final URL:

http://boston.conman.org/2000/08/01

You can also specify the entire month by leaving off the day portion. You can even select an arbitrary portion of time.

You may also note subtle shading of the links and that's intentional: the “closer” the link is (relative to the page) the “brighter” it appears. It's an experiment in using color shading to denote the distance a link is from here. If you don't notice it, don't worry; it's not all that important.

It is assumed that every brand name, slogan, corporate name, symbol, design element, et cetera mentioned in these pages is a protected and/or trademarked entity, the sole property of its owner(s), and acknowledgement of this status is implied.

Copyright © 1999-2019 by Sean Conner. All Rights Reserved.