make tests run faster

[tombentley]

My biggest complaint about ceylon.test at the moment is that it's simply too slow at running the tests. Can we find out what's makes it slow?

[FroMage]

+1 we need to profile it.

[thradec]

Any tips what tool to use? I already tried jvisualvm, but without success.

[FroMage]

Mission control i think it's called, or flight recorder. It's in oracle Java 7

[renatoathaydes]

This is particularly true when you group your tests in a class, rather than using top-level functions. Each test method (even without doing anything) takes something like a full second to run.

[renatoathaydes]

I've found out where the bottleneck is. The DefaultTestExecutor method called findCallbacks is responsible for over 90% of the time it takes to execute a simple test class with 6 test methods, which each just printing something to the console and doing nothing else.

I was able to reduce the time it took to execute the 6 tests from, consistently over 5 seconds, to below 1 second, by caching the FunctionDeclaration[] callbacks, using the following as a key:

classDeclaration.string + typeLiteral<CallbackType>().string

Probably not the best choice of a key, but at least this guarantees you'll always get the same callbacks of type CallbackType for a given classDeclaration.

If you want I can submit a pull request with this change later, just can't do it now as I performed several experiments before arriving at this, so I need to do some cleanup first :)

Now, the question that remains is just why findCallbacks is so slow!

Here's the time it takes in my machine to run this method on my tiny class of 6 test methods, which does not even have before and after callbacks:

Find callbacks for class test.ceylon.test.suite::TestHolderceylon.test::BeforeTestAnnotation
beforeCallbacks verified in 575 ms
Find callbacks for class test.ceylon.test.suite::TestHolderceylon.test::AfterTestAnnotation
afterCallbacks verified in 306 ms

[renatoathaydes]

BTW I also added a cache to the verification of the classDeclaration, because for each test method inside a class, the exact same check will be made again and again... though it usually takes just a couple of ms to verify the class, I believe it is worth adding a few more lines of code to cache this to avoid doing totally unnecessary work potentially dozens, even hundreds of times for large test classes.

[lucaswerkmeister]

On classDeclaration =String.declaration, functionDeclaration =String.clone.declaration, visit is called 126 times with a non-null decl argument (168 times total), but with only 11 distinct non-null decl arguments. Maybe we could check “did we already visit this?”

gist

[lucaswerkmeister]

Changing the

if (exists decl)

to

if (exists decl, !all.contains(decl))

(all being the set of arguments I introduced for the arguments counting, see the gist linked above) improved the time from ~1000ms to ~430ms.

[lucaswerkmeister]

I’ve added a patch file to the gist linked above; @renatoathaydes maybe you can include this in your pull request? (git apply, paste patch, then hit Ctrl+D.)

[renatoathaydes]

Hi @lucaswerkmeister ... by the time I saw this, I had already found a different solution. Could you please test my PR with your tests? I want to make sure it didn't break anything and that the speed is now acceptable. PR: https://github.com/ceylon/ceylon-sdk/pull/235

[thradec]

Thanks a lot @renatoathaydes and @lucaswerkmeister for your investigation and measurement!

(When I wrote it, I hoped that our metamodel will be super fast and these caching mechanisms won't be necessary ;-))

[renatoathaydes]

You're welcome! That's how it is, you write beautiful code just to later find out it runs too slow, then you find where it's slow and fix it :) Hopefully, without making it less beautiful. Don't worry about what you call "keeping state between runs"! That's metamodel information that we're caching for speed, not test information, so test runs are still completely independent. There's absolutely nothing wrong with caching stuff (I'd argue it's wrong not to). Try disabling your browser's cache :)

[renatoathaydes]

Anything else you want me to do to get this merged?

[thradec]

@renatoathaydes last minor thing, can you please rebase your commits into one and push with force

[lucaswerkmeister]

@thradec squashing a weekend’s worth of work into a single commit? Why? Sure, some of the revert and amend commits can be squashed, but stuffing it all into a single commit sounds crazy to me.

[thradec]

@lucaswerkmeister the result is several changes in one file, 14 separate commits (some of them contains changes, which are removed later) seems little much to me, I would prefer clean git history

[lucaswerkmeister]

I think that at least 2c7e434 “Optimized DefaultTestExecutor.findCallbacks method”, 60259f6 “ Merged visitors that look for callbacks in DefaultTestExecutor” and efe1bd2 “DefaulTestExecutor now caches callbacks for top-level function tests as well as class tests” sound like they’re separate enough to be kept (and the other commits would then be squashed into the appropriate one of these three).

But I haven’t kept up with all the changes, so I’m not sure how independent they really are. If you think that they really just do one thing, squash them.

[thradec]

I didn't want to bother Renato, with such detailed polishing ;-) (btw. commit 60259f6 introduce bug with callbacks order)

[lucaswerkmeister]

I didn't want to bother Renato, with such detailed polishing ;-)

Agreed, it’s pretty complicated… I’m not sure how many Git clients even offer a full interactive rebase.

Also, after looking through the commit messages, it seems most of them are really fix commits, which should definitely be squashed. So I guess I’d be okay with a big squash :)

commit 60259f6 introduce bug with callbacks order

Then bd569f2 would be squashed into this commit? (Is that the right commit? Looks different.)

[thradec]

Done, via #236 pull request.

[tombentley]

Thanks everyone!