further unit test speedups and cleanups - #9226
Conversation
We have a custom Logger in lib/github.py that's used for a single testcase that wants to check what is being fetched. We can easily manage this with the standard Python logging facilities. Add a per-file logger and use that instead, and use .assertLogs() in the test. This also means that the requests will be visible in our scripts that support `--debug`/`-d` arguments. Switch one other existing (global) log call to the new per-file logger. Finally: a very interesting thing to know is where the github token came from, or if we have one at all. Add some debugging about that.
8048a3f to
b634485
Compare
Our various tests which use test_mock_server can't be run in parallel
for two main reasons:
- we statically bind to a hardcoded port number. This means that our
tests can't run against each other but also means that we could just
get unlucky with other things running on the system
- test_job tests share a single `.json` file in a temporary directory
which we create (and never delete) in /tmp which means they see each
others data.
Add two queues to test_mock_server:
- the first replaces our "ready" event, recently added in a1f707c
("lib/test_mock_server.py: wait for server startup") with a queue.
We await the queue to find out when we're ready to serve but the
queue passes back the listener port number. This allows specifying
the port number as 0 (which all of our tests now do) and finding out
which port was kernel-allocated on the server side. Why provide the
address at all if all of our tests use 0? Because this code is also
used by the mock-github script in the cockpituous repository and it
needs a static address.
- a generic other queue which can be optionally used by tests to pass
data back to themselves from their handlers. This replaces the JSON
file.
Improvements:
- no dangling temporary directories left behind in /tmp each time we
run the tests
- no conflicts with other processes running on the system (including a
guaranteed conflict with a parallel run of the same tests, perhaps
in a different worktree)
- enables running the test suite under xdist, if you so fancy
- less code, more self-contained
These tests are the worst remaining offenders in slowing down the test suite. Make two fixes. For the aio "github api flakes" test, we want to test retry behaviour but the retries have an exponential backoff that we have to wait for (but never test). We can kill two birds with one stone by replacing the sleep with a mock which means that we don't have to wait for it and can verify that the exponential backoff is working properly. For the cache tests, they're also slow because we do long sleeps — six seconds in total. Reduce our Cache lag= to 1 second instead of 3 and sleep for fractional seconds instead. We could probably go even lower with a fractional lag but I'm worried about stability through scheduling blips on busy machines. We can't use sleep mocking here as easily because this is testing timestamps on the filesystem, but let's keep things simple: this is already enough of an improvement. With this change the tests drop from requiring ~12s (or ~42s at the start of the week) to ~4s.
b634485 to
5785529
Compare
| self.token = match.group(1) | ||
| logger.debug("github token loaded from %s", f.name) | ||
| else: | ||
| logger.debug("no oauth_token found in %s", f.name) |
There was a problem hiding this comment.
Is "oauth token" the same as "github token" in this context? Why does this message say "oauth token"?
There was a problem hiding this comment.
Ah, this is saying "no oauth_token assignment in the config file", got it.
There was a problem hiding this comment.
Ya this is specifically about the case where (as a final fallback option) we raid the gh cli config and look for an existing token but fail to find it.
| self.api.cache.mark(time.time() + 1) | ||
| self.api.get("/test/user") | ||
|
|
||
| self.assertEqual(logs.output, [ |
There was a problem hiding this comment.
Indentation? Doesn't this need to be under the with ... as logs: statement?
There was a problem hiding this comment.
no. it doesn't. and maybe even shouldn't. the inside the with: is the thing under observation and the outside of it is the inspection of what happened during that observation period.
compare that also with the assertRaises for example where it's even more clear why you'd want it that way:
with self.assertRaises(ValueError) as cm:
do_something()
self.assertEqual(str(cm.exception), "invalid value")
self.assertEqual(cm.exception.args, ("invalid value",))because you can't do the compare until after the exception, but the exception is going to shoot you out of the block.
There was a problem hiding this comment.
Aha, thanks! I was mostly suprised that "logs" is even available outside of the "with". TIL!
|
|
||
| def test_current(tmp_path: Path) -> None: | ||
| c = cache.Cache[object](f'{tmp_path}', lag=3) | ||
| c = cache.Cache[object](f'{tmp_path}', lag=1) |
There was a problem hiding this comment.
Isn't this a bit of a micro-optimisation
There was a problem hiding this comment.
This change is the single biggest improvement in test run times... there's just no need to wait that long... I nearly changed it to 0.1...
3 participants
This is another low-hanging fruit hunt which further improves the single-threaded speed of the unit tests (now down to ~4s from an original ~42s) and makes it possible to parallelize them. It's also a net decrease in complexity and lines of code (mostly due to removing the json logfile stuff).
Building on #9223 and conflicting #9224 due to the shared first commit.