Test suite is slowwwwwwww on OCMock 3 about ocmock HOT 42 CLOSED

To be honest I can't think of any reason that would make OCMock 3 noticeably slower. What kind of slowness are we talking about? A few milliseconds per test? Or are there specific tests that have added several seconds each?

from ocmock.

Executed 457 tests, with 0 failures (0 unexpected) in 47.889 (47.953) seconds

-vs-

Executed 455 tests, with 0 failures (0 unexpected) in 2.226 (2.544) seconds

This is going from my OCMock 3 branch to my OCMock 2 branch. I was quite generous w/ 2-3x slower. As you can imagine, this is a massive impact on our productivity.

We upgraded a few other pods but they were dot releases so nothing major. I will verify it isn't one of those pods in a sec just to make sure I'm not barking up the wrong tree.

from ocmock.

Executed 457 tests, with 0 failures (0 unexpected) in 162.916 (162.994) seconds

^ A slower computer than mine just reported this. #fyi

from ocmock.

Nope, reverted all other pods (other than OCMock) to the older versions and it is still crazy slow.

I'll dig in and see if something isn't mocked for our data requests or something. That could obviously cause some slowness if it is hitting the server.

I've noticed basic mocks fail on 3 that worked in 2. It has caused some headache but it could be the issue we're seeing.

Update: I went through one of our easier suites and played w/ them as much as possible to make them faster and it still takes ~2.9s for the suite of 24 tests. It is wayyy longer compared to ~0.4s for 53 tests in master.

Our setup is Specta, Expecta and OCMock.

from ocmock.

Thank you for investigating this further. This is really curious. The OCMock test suite itself, which when built for OS X comprises 216 tests, runs in little over 1 second on my laptop. And it obviously uses OCMock quite heavily. So, it seems that there's nothing inherently slow about OCMock.

What could be different in your environment? Of the 24 tests you ran, are there particular tests that have become slow? Or does using OCMock 3 seem to add a little overhead to each of the 24 tests?

from ocmock.

No prob.

The only thing I've noticed is the majority of our slower tests [roughly 22-25 of the 47 seconds noted above] were around testing view controllers.

This is the way we grab our view in a beforeEach:

    beforeEach(^{
        UIStoryboard *storyboard = [UIStoryboard storyboardWithName:@"Board" bundle:nil];

        subject = [storyboard instantiateViewControllerWithIdentifier:@"tutorial"];

        subjectMock = [OCMockObject partialMockForObject:subject];
    });

This is from the suite that takes 2.9s from above. Obviously this is the old syntax but that wouldn't cause a lot of problems, would it?

from ocmock.

The new syntax is implemented on top of the selector-based syntax. So that shouldn't be a problem.

A major implementation change in OCMock 3 was the introduction of verify-after-running. To make this work the mocks now basically stub each and every method when they are created. (They have to so that they can record all invocations before they know what will be verified.) My suspicion at this point is that maybe the mere use of some runtime introspection triggers some code in the story board or view controller, which takes a bit of time to run. Unfortunately, I can't think of a good way to debug this.

One thing that may be worth trying, given that it seems you're building OCMock from source anyway, would be to make a small change in OCPartialMockObject. Could you change lines 134-135 from

if(types == NULL)
    types = ([[mockedClass instanceMethodSignatureForSelector:selector] fullObjCTypes]);

to

if(types == NULL)
    return;

and see whether that makes any difference?

from ocmock.

I changed it and it had no effect. That line is never hit. I stepped through the code and I see it is traversing the entire class signature plus the parent.

from ocmock.

You could be mocking a very core NSObject / UIApplication / other method which gets called a lot, but which OCMock turns into an NSInvocation-forwarded version every time (which is much slower than a normal method call, though fast enough to not be a problem unless it is called a lot). Or maybe a class method on say NSString, or some other commonly-used class, or there is some bad interaction with other frameworks you are using. Trick would be finding which one. That is another problem with wrapping every single method on a class; if you mock core framework classes you might hit a very sensitive method at some point.

from ocmock.

So would it be better to use partial mocks to avoid having to mock "all the things"?

from ocmock.

Partial mocks do mock all instance methods. Class mocks mock all class methods on a class. You might try finding the handleUnRecordedInvocation:(NSInvocation *)anInvocation method in OCMPartialMockObject class, and putting an NSLog of which selector it is forwarding along, then run a small test suite to see if there is an inordinate number of calls to a particular method. Then do the same with the forwardInvocationForClassObject: method in OCMClassMockObject.

from ocmock.

@johnbland-wf Just did some profiling and it looks like the bulk of the time is spent in partial mock setup, mostly this line:

Is it possible that the earlier versions of OCMock took a more "lazy swizzling" approach in setting up method forwarding, and this slowdown we're seeing is related to the overhead of setting up forwarding for all methods up front?

from ocmock.

Ooh. Are we checking that we are not re-wrapping class methods that have already been wrapped by previous mocks? Or are we wrapping them all thus doubling the number of methods every time we mock a class?

from ocmock.

That seems like it could be the case @greglittlefield-wf, great find.

I have no problem doing more testing @carllindberg. Let us know if you found anything specific in the library.

from ocmock.

Any progress on this guys? 3 is killing our productivity.

from ocmock.

I've looked into this and added the following test to the iOS7 example project:

- (void)testCreationOfPartialMocks
{
    for(int i=0; i<100; i++)
    {
        MasterViewController *controller = [[MasterViewController alloc] init];
        id controllerMock = OCMPartialMock(controller);
        [controller tableView:nil commitEditingStyle:UITableViewCellEditingStyleInsert forRowAtIndexPath:nil];
        [controllerMock description];
    }
}

When I run the iOS version in the simulator, Instruments says that it takes about 7s. Inverting the call tree shows that the biggest chunk is about 2.7s spent in search_method_list():

Drilling into this I can see how that's called from different places during the setup of the stubs when creating the mock:

I've tried a few things to reduce the number of calls but I haven't come up with anything that makes a major difference.

from ocmock.

Also seeing this issue on our test suite. Takes around 50x more time on OCMock v3. However I don't think that we actually have any UIViewController mocks. Mostly just mocking custom NSObject subclasses.

from ocmock.

Could you share an order of magnitude? How many tests per second did you see with OCMock 2 and how many tests per second do you see with OCMock 3? From my experiments it seems that currently with OCMock 3 it can take about 0.1s to create a partial mock. Is this what you are seeing?

from ocmock.

I've just pushed a change that should improve things somewhat. If you have a chance, could you check whether it makes things better for you, too? Not saying we're there yet.

from ocmock.

We have 899 tests and our run time jumped from 37-40s on 2.2.4 to 257-273s on 3.0.2. I've tried the latest commit (999b843) and got 121-125s, so you're definitely onto something here!

from ocmock.

We attempted to run it here but :head kept crashing on tests so we couldn't confirm. I'll try in a few once I get to a stopping point.

from ocmock.

We had around 299 tests total that were running at around 1.1 seconds, now takes around 50 seconds on average. Tried pulling the latest but it seemed to be crashing when running the tests, can test again later.

from ocmock.

This is odd. The changes I made involve string comparisons and regex matches on class and method names. I'm curious how this can cause crashes. Could you post a stack trace?

from ocmock.

On second thought. I've also merged #115 since the release of 3.0.2, and this does have potential to introduce crashes. Even more interested in the stacktrace. @carllindberg are you watching this?

from ocmock.

Here is what I see:

It also consistently chews up memory and cpu when running tests.

from ocmock.

I have not had time to try and really look at this problem. #115 should not cause any slowdowns, as the new code in there should only be invoked when @encode(val) does not equal the NSValue objCType, which was always an error in OCMock 2.x. If there are coding errors in there, it of course could cause crashes, but again that would only happen in situations which were errors with 2.x but we are now a bit more lenient with. I'd think any crashes caused by it would pretty obviously point to that code.

Avoiding Apple private methods should help a lot, though that is error prone -- that will also probably skip any category methods people add to Apple classes which use the "prefix_methodName" convention, and who may expect to be able to call/stub/expect.

Still, it does mean that an awful lot of methods which were once simple method calls are now going to be a pair of NSInvocation calls -- one to forward from the real object back to the mock to record the call, then the mock back to the method on the real object. And for some NSObject protocol methods like respondsToSelector and many others, it won't forward back to the real objects, since the mock (via the NSProxy class or overrides) implement the methods already, so hopefully those implementations work OK as substitutes.

Another thing is that we are continually modifying classes in the runtime, which flush any of the method lookup caches on that class and all subclasses, such that the caches have to be rebuilt on subsequent calls -- but then the mock tear downs or next unit test probably flushes them again. That was happening to an extent before but it may be much more noticeable now. If search_method_list is a big percentage of the time, that indicates that the method caches are missing a lot, I'm pretty sure.

There is some caching that we could do possibly -- maybe keep an NSArray (or NSHashTable) of the found selectors for a given class so we don't have to figure them out again for the same class. And maybe the NSMethodSignature instances too. The new NSRegularExpression should possibly be cached as a global variable. Although with its current implementation a pair of hasPrefix calls on the NSString may be faster.

It's also possible that by not forwarding some methods now, we are actually exposing ourselves to some other methods which should be blacklisted but currently are not. The above crash screenshot is obviously during the forwarding games played by the swizzling, but I'm not sure of the exact cause -- the backtrace is not all the way expanded. Looks like it dies in class_isMetaClass though which is a bit scary, as a bad pointer was passed in there it looks like. Actually I just upgraded to 10.9 and ran the tests and am getting a similar crash when I do some stuff with UITableView -- it looks like it's crashing when forwarding on some of the internal UIAppearance calls. That stuff is a certain amount of voodoo and I'm not sure how we are affecting it, but we apparently are. Hmm... I think your magic meta-subclasses are not initialized right away, which can get +initialize called again on your sub-metaclass, which seems to be causing trouble (UITableView +initialize sets up some UIAppearance stuff and I think that is a bad idea with your custom meta classes). I added "[subclass self]" right after "id newMetaClass = object_getClass(subclass);" to get initialize called before we play any further runtime games with it, and it seemed to avoid the immediate UITableView problem. You probably want to add an empty implementation of the +initialize method to those magic subclasses so that the superclass version isn't called again -- not all implementations guard against being called more than once when subclasses exist.

I also worry if using mocks on proxy-type objects which forward to other objects won't be handled very well (since they won't have actual implementations to stub out, though method calls do flow through them).

from ocmock.

Class traversing should definitely get cached. At a quick look, 2 seemed to cache but 3 doesn't.

from ocmock.

As an intermediate progress report; in 3c79446 I have added code that creates a +intialize method in the special subclass created by the mock.

from ocmock.

@johnbland-wf Just to confirm, are you still seeing your test suite crash with the latest version of OCMock? And the crashes are in class_isMetaClass() as shown in the screenshot?

from ocmock.

Not only did it not crash, the suite finished in 34 seconds. That's an improvement seeing as we went from 457 tests to 489 tests. So more tests and faster speeds.

It's getting there! :-D

from ocmock.

You probably want to add +load and +initialize to the blacklist, just to be safe. You might also want to add the empty +initialize to the OCPartialMockObject subclasses, to be safe there as well. The blacklists should also probably be NSSets, and created only once.

from ocmock.

Now that we are already ignoring all class methods in NSObject would it still make sense to put +load and +initialize on the black list? This would only apply to implementations in subclasses.

Interesting. I, too, thought that the partial mock subclass should have an empty initialize method. However, with the current implementation this doesn't seem necessary. I've added a test to document this.

To be honest, I haven't benchmarked whether an NSSet would really be faster than an NSArray for such small number of objects. In either case the calls to containsObject: are quite far down on the overall cost, so I'm inclined to go with the simpler code.

from ocmock.

@johnbland-wf With the latest commits (0adc653) I think we are at a point where further performance improvements would require major changes, e.g. an API to disable verify after running. I'm a bit reluctant to do this. How comfortable are you with the performance of OCMock after the changes made now?

from ocmock.

Before last commit:
Executed 531 tests, with 0 failures (0 unexpected) in 67.579 (67.705) seconds

After:
Executed 531 tests, with 0 failures (0 unexpected) in 9.258 (10.207) seconds

from ocmock.

Any chance this is releasing soon?

from ocmock.

Interesting that stubbing +initialize is not necessary. We are creating a legitimate subclass, and I would have thought called methods on it, which should initialize the subclass first (potentially calling the superclass version again if not overridden). As for the blacklist, might as well. It's not the NSObject versions of those methods we would worry about. +load should honestly be called before OCMock has a chance to do anything so it shouldn't matter.

As for NSSet vs NSArray, yeah, shouldn't matter much. Creating them only once inside a dispatch_once block would seem to be an easy enhancement though.

If you are trying to speed up the stret checks, you could probably put the cache right inside the NSMethodSignature method. The class doesn't matter; you could cache directly on the objcType string, which would be a simpler key creation and result in way more cache hits. The class of the receiver doesn't really matter, it's the return type only. If you wanted to go hardcore, you could create a CFDictionary with custom callbacks which take c-string arguments (making copies if need be) and integer values, which wouldn't need to do any allocation at all for cache hits.

from ocmock.

@carllindberg Not sure I understand your last suggestion. You're saying that we could put the cache into the NSMethodSignature method because it only depends on the objcType. It's true that the type string is a sufficient cache key, but getting the type key requires looking up the NSMethodSignature instance and that is the most expensive part of the operation... Caching on the selector name only isn't sufficient because a method with the same name could have different return types. This is why I settled on the class/selector cache key. Doesn't that make sense?

from ocmock.

@johnbland-wf Couldn't spend much time on OCMock recently. A release should be out soon very soon, though.

from ocmock.

All good. We're just targeting that commit at the moment. :)

from ocmock.

Thanks for the speed improvements. Things seem back to the fast OCMock 2 speed on 3.1 :)

from ocmock.

++ the latest 3.1.1 speed improvement is unbelievable

Before

Executed 62 tests, with 0 failures (0 unexpected) in 4.346 (4.367) seconds
Executed 148 tests, with 0 failures (0 unexpected) in 13.734 (13.792) seconds

After

Executed 62 tests, with 0 failures (0 unexpected) in 0.286 (0.312) seconds
Executed 148 tests, with 0 failures (0 unexpected) in 0.338 (0.393) seconds

from ocmock.

Agreed. I just noticed the new release. This puppy is good to go.

Great work!

from ocmock.