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 25, 2021

The case of the regression test regression, part III

When I last left off I identified the slow code in the regression test and it left me puzzled—it was a single function call that was called during startup and not when the tests were running. Faced with the fact that I had identified (for a second time) that code that did not change was causing a second of delay, I decided to change my approach. Instead of starting with the working, fast version of the code and going forward, I would start with the current, slow version of the code and work backwards. The first point of business—see if I could reproduce the fast code/slow code change with the code I identified as a sanity check. And of course that sanity check failed as both code versions were now slow.

What was that Sherlock Holmes quote? Ah yes, “When you have eliminated the impossible, whatever remains, must be the truth.” Must be the computer hates me.

Okay, so now that the slowdown was not the regression test script, but one of the mocked services. So I did to that script what I did to the regression test script—record how long it takes to handle a query. And of course it always responded in a timely fasion. No second long delay found at all!

So the delay is not in the regression test. The delay is not in the mocked service. I am slowly running out of ideas.

Okay, time to take stock: what do I know? Some queries are taking up to a second to run. They appear to be the same tests from run to run. Okay, let's run with that idea.

I modify the regression test to kick out which test cases are taking over 900,000 microseconds. I then just run those tests and yes, it's consistent. I remove those slow tests, the regression test just flows. If I just run the “slow” tests, each one takes about a second to run.

So now I know it's consistent. What's consistent about them?

Now I start digging into the logs and … yeah … something odd is going on with those tests. It's a path that “Project: Lumbergh” can take, and it's hitting a mocked service that I keep forgetting about. I mean, the regression test starts it up, but otherwise, it's pretty silent (and pretty easy to forget about). I add some logging to this particular mocked service, run the regression test and see that it responds once, then nothing ever again.

I add logging to the “fast” version and yes, it gets hit, and keeps responding.

I check the differences between the two versions:

[spc]saltmine-2:~>diff path/to/slow/version path/to/fast/version
96c93
< nfl.SOCKETS:insert(sock,'r',function()
---
> nfl.SOCKETS:insert(sock:fd(),'r',function()
106c103
< nfl.server_eventloop()
---
> nfl.eventloop()
[spc]saltmine-2:~>

Yeah … just some API updates, like yesterday. But if I run the new regression test while running the older version of this one mock, the new regression test runs as I expected. The delay is actually coming from “Project: Lumbergh” because the new version of this mocked service doesn't respond properly, causing “Project: Lumbergh” to time out, thus the delay I'm seeing.

I think I'm finally getting somewhere, but why is it so hot? And what am I doing in this basket?

Obligatory Picture

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

Obligatory Contact Info

Obligatory Feeds

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-2021 by Sean Conner. All Rights Reserved.