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.

Monday, September 16, 2019

♫Sleigh bells ring, are you listening?♫

Bunny and I went to the Cracker Barrel for dinner, and in … wait a second! I'm getting a strong feeling of déjà vu at the moment …

Only this time it's mid-September and not late-July, and it wasn't just a few items, but half the store was given over to Christmas. The other half was themed with Thanksgiving in mind.

And on one lone table was the Hallowe'en display.

Sigh.

Thursday, August 29, 2019

Okay, so I wasn't really done with the profiling

Last week I was surprised to find this bit of Lua code as the hot spot in “Project: Sippy-Cup:” 

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

Last night I realized that this code was stupid in this context. The code was originally based upon the original IP address parsing module which converted the text into a binary representation of the code. So in that context, converting the text into a number made sense. When I made the text-only version, I did the minimum amount of work required and thus, left in some sub-optimal code.

But here? I'm just looking at text, expecting up to four hex digits. A string of four hex digits will, by definition, always be less than 65,536. And LPeg has a way of specifying “up to four, but no more” of a pattern. It's just:

local h16 = HEXDIG^-4

I made that change to the code, and reprofiled “Project: Sippy-Cup.” It didn't change the results at the C level all that much (the LPEG C function merge() is still third, as I do quite a bit of parsing so that's expected), but the results in Lua are vastly different—it's now the code that verifies the incoming phone numbers that's the hot spot. It doesn't surprise me very much as we do that twice per request (one for the caller, and one for the recipient), and it's not nearly as bad a hot spot as the above code was.

Thursday, August 22, 2019

Through Windows Darkly

I arrived to The Ft. Lauderdale Office of the Corporation to find a package sitting on my desk. It had finally arrived—the Corporate Overlords' mandated managed laptop.

It's only been a year and a half that we've been threatened by promised new managed laptops to replace the self-managed ones we currently use, but in the end, it was decided to let us keep our current machines and use the new “managed laptops” to access the Corporate Overlords' network. I think this was decided due to the cultural differences between The Corporation and the Corporate Overlords—we're Mac and they're Windows.

Yes, of course the new managed laptop is a Windows box.

It's a Lenovo ThinkPad T480, and compared to the current laptops I have at work, a Linux system with 4 2.8GHz CPUs with 4G RAM and a Mac with 8 2.8GHz CPUs and 16G RAM, it's a bit underpowered with 4 1.8GHz CPUs and 8G RAM. I will admit that the keyboard is nicer than the keyboards on my existing laptops, but that's like saying bronchitis is better than pneumonia—technically that's true, but they're still bad. It looks like I'll have to break out another real keyboard from the stash.

The laptop was thinner than I expected, and the build feels solid. Lots of ports, so that's nice. The screen is nice, and the built-in camera has a sliding cover so I don't have to spoil the sleek asthetic with a tab of electrical tape.

The real downside for me is the software—Windows. I can hear the gales of laughter from my friend Gregory when he hears I have to suffer Windows. The last time I used Windows was … um … 1999? It's been a while, and not only do I have to get used to a nearly alien interface, but one that I have little control over.

Well, I have a bit of leeway—I was able to install Firefox so it isn't quite that bad, but there's a lot I can't do; external block storage devices are blocked outright, there are some websites I can't visit and editing the Windows Registry is right out! Not to mention the crap ton of anti-viral, anti-spam, anti-phishing, anti-development, corporate-friendly “productivity” software installed and running on the machine.

This is something I have never experienced. Until now, every computer I used at a company has never been this locked down, not even at IBM. It's going to take some adjustment to get used to it.

Meanwhile, I've been poking around on the system and—“End of Day Restart” …

“End of Day Restart?”

Seriosly, Microsoft? You automated the daily reboot?

Wow … this is definitely going to take some time to get used to …

Wednesday, August 21, 2019

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.

“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.

Tuesday, August 20, 2019

Profiles of Lua code

I started “Project: Sippy-Cup” six years ago as a “proof-of-concept” and it ended up in production (without my knowledge and to my dismay at the time) about a year or two afterwards. The code was written to be correct, not fast. And for the past four or five years its been running, performance has never been a real issue. But that's changing, as the projected traffic levels shoot past the “oh my” and into the “oh my God” territory.

“Project: Sippy-Cup” processes a lot of SIP messages, which are text based, so there's a lot of text processing. I use LPEG for ease of writing parsers, but it's not necessarily as fast as it could be.

There are two issues with LPEG—it has infinite look-ahead, and ordered choices. So the code that checks for the SIP method:

method = lpeg.P"ACK"
       + lpeg.P"BYE"
       + lpeg.P"CANCEL"
       + lpeg.P"INFO"
       + lpeg.P"INVITE"
       + lpeg.P"MESSAGE"
       + lpeg.P"NOTIFY"
       + lpeg.P"OPTIONS"
       + lpeg.P"PRACK"
       + lpeg.P"PUBLISH"
       + lpeg.P"REFER"
       + lpeg.P"REGISTER"
       + lpeg.P"SUBSCRIBE"
       + lpeg.P"UPDATE"
       + (lpeg.R("AZ","az","09") + lpeg.S"-.!%*_+`'~")^1

will first compare the input to “ACK”; if it doesn't match, it then backtracks and tries comparing the input to “BYE”, and so on down the list until it gets the last rule which is a “catch-all” rule. It would be easy to reorder the list so that the checks are “most-likely” to “least-likely,” but really the entire list could be removed leaving just the catch-all:

method = (lpeg.R("AZ","az","09") + lpeg.S"-.!%*_+`'~")^1

I have the same issue with SIP headers—there are 100 headers that are “parsed” (for various values of “parsed”) but I only really look at a dozen headers—the rest just slow things down and can be passed by a generic parsing rule. The full headers were added during the “proof-of-concept” stage since I wasn't sure at the time which headers would be critical and which ones wouldn't, and I've never gone back and cleaned up the code.

Another aspect is the sheer number of validity checks the code makes on the incoming SIP message. Many of the checks don't really have any effect on the processing due to managerial mandate at the time, so they could go (I wanted strict checking that bailed on any error; my manager at the time did not want such strictness—no need to guess who won, but I still track parsing irregularities).

So while I feel these are two areas where the code could be made faster, I don't know if that's where the time is spent, and so it's time to profile the code.

The issue now is that the system profiler will profile the code as C, not as Lua. I don't need to profile the code to know the Lua VM gets called all the time. What I need to know is what Lua code is called all the time. But it can't hurt to try the system profiler, right? And given that the regression test has over 12,000 test cases, we should get some good profiling information, right?

Original Profile—Each sample counts as 0.01 seconds.
% time cumulative seconds self seconds calls self ms/call total ms/call name
13.32 3.47 3.47       match
12.74 6.79 3.32       luaV_execute
9.31 9.22 2.43       luaS_newlstr
6.83 11.00 1.78       luaD_precall
5.31 12.38 1.39       luaH_getstr
3.38 13.26 0.88       luaD_poscall
2.57 13.93 0.67       index2adr
2.19 14.50 0.57       luaV_gettable

Not bad at all. The function match() is the LPEG execution engine, which matches my intial thoughts on the code. It wasn't much work to remove extraneous SIP headers I don't bother with, and to simplify the method parsing (see above). Re-profile the code and:

Modified LPEG—Each sample counts as 0.01 seconds.
% time cumulative seconds self seconds calls self ms/call total ms/call name
14.25 3.67 3.67       luaV_execute
11.22 6.56 2.89       luaS_newlstr
10.49 9.26 2.70       match
6.33 10.89 1.63       luaD_precall
5.20 12.23 1.34       luaH_getstr
2.76 12.94 0.71       index2adr
2.58 13.61 0.67       luaD_poscall
2.41 14.23 0.62       luaV_gettable

match() drops from first to third place, so that's good. And a load test done by the QA engineer showed an easy 25% increase is message processing.

But that's really as far as I can go with profiling. I did a run where I removed most of the validation checks (but only after I saw none of them were triggered over the past 30 days) and didn't see much of a speed improvement. So I really need to profile the Lua code as Lua code and not as C.

That's going to take some work.

Monday, August 19, 2019

Notes on an overheard phone conversation at The Ft. Lauderdale Office of The Corporation

“Hello?”

“Yes, who is this?”

“Who is this”

“This is … Sean.”

“And this is … XXXX [of the IT department].”

“Okay.”

“This is in reference to … ”

“Your email … ”

“About … ”

“Um … the laptop?”

“Oh yes! Sean! Of course! See, I get a lot of spam calls these days.”

“Yeah, I get a lot of phishing emails from you guys these days.”

“Ha!”

Wednesday, August 14, 2019

“Here's a nickel kid. Get yourself a real computer”

“Here you go, kid,” said Dad, as he handed me a book with a bright yellow jacket. “I heard this ‘Linux’ is the next up-and-coming thing in computers.”

I look at the title: Linux for Dummies: Quick Reference. “Um … thank you. You do realize I run Linux both at home, and at work, right?”

“Hey, maybe you can learn something from it.”

So I'm skimming through the book and … elm? pine? rsh? FVWM? When was this book written? … Oh … 2000. That explains it. Everybody these days are running mutt, ssh and GNOME.

It'll fit nicely on the shelf next to Sams Teach Yourself TCP/IP in 24 Hours and Inside OS/2.

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.