Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Poor Performance with lots of Prototype Scoped Beans [SPR-9670] #14304

Closed
spring-projects-issues opened this issue Aug 7, 2012 · 8 comments
Closed
Assignees
Labels
in: core type: enhancement
Milestone

Comments

@spring-projects-issues
Copy link
Collaborator

@spring-projects-issues spring-projects-issues commented Aug 7, 2012

Kevin Mudrick opened SPR-9670 and commented

We are seeing a pretty substantial performance hit with the creation of large quantities of prototype-scoped beans in the 3.1.x branch versus 3.0.x (and 2.5.6)

In our example, we have call context.getBean() with a bean consisting of 2 levels of nested bean referenced, in a pretty large loop.

3.0.7: 40604ms
3.1.2: 685150ms

The only difference between these runs is the version of the spring dependencies.

After profiling using YourKit, I found the hotspots in 3.1.x to be in the following places:

org.springframework.beans.TypeConverterDelegate: This seems to be the bigger problem.
The changes introduced in 3.1 (specifically, in commit 6f14673) to findDefaultEditor() end up (expensively) initializing an editor registry every time this is called. Since we get here each time we apply a property on every bean creation, this really adds up. Previously, the commented-out code ended up shortcutting this. I found that replacing the commented out code (the part that relied on the now-removed PropertyTypeDescriptor/PropertyDescriptor with static use of PropertyEditorManager.findEditor(), cuts down on the slowness considerably, at the expense of relying on java.beans - which a few commit comments seem to indicate is something to be avoided for better platform compatibility.

org.springframework.core.convert.Property: This also seems to be a problem.
The overhead of the annotation parsing via reflection is already noted in #13981 - but that issue doesn't seem to mention this example. My profiling is showing that this is being constructed for every property found on every bean being created. With lots of prototype beans - this comes to light pretty quickly. Perhaps if ReflectionUtils used a similar caching strategy to apache commons-beanutils PropertyUtilsBean for annotations, this performance hit could be mitigated.


Affects: 3.1.2

Issue Links:

  • #13981 org.springframework.core.convert.Property class performs expensive operations in its constructor ("is duplicated by")
  • #12081 Concurrent prototype creation causes NullPointerException
  • #13109 TypeConverterDelegate contains commented out code

0 votes, 6 watchers

@spring-projects-issues
Copy link
Collaborator Author

@spring-projects-issues spring-projects-issues commented Aug 7, 2012

Kevin Mudrick commented

Added test case which illustrates the performance difference (if you update the pom & re-run to switch between 3.0.7 and 3.1.2). Pull request: spring-attic/spring-framework-issues#33

Here are the results I get running locally:

3.0.7

Running org.springframework.issues.ReproTests
StopWatch 'Prototyped Bean Creation': running time (millis) = 6609


ms % Task name


00906 014% Initializing
05703 086% Creating

3.1.2

Running org.springframework.issues.ReproTests
StopWatch 'Prototyped Bean Creation': running time (millis) = 66891


ms % Task name


00872 001% Initializing
66019 099% Creating

As you can see, creating lots of prototype-scoped beans is over 10x slower, while initialization is roughly the same.

@spring-projects-issues
Copy link
Collaborator Author

@spring-projects-issues spring-projects-issues commented Aug 7, 2012

Chris Beams commented

Thanks, Kevin.

@spring-projects-issues
Copy link
Collaborator Author

@spring-projects-issues spring-projects-issues commented Aug 7, 2012

Chris Beams commented

Just confirmed these results on my machine as well:

3.0.7

Running org.springframework.issues.ReproTests
StopWatch 'Prototyped Bean Creation': running time (millis) = 5326
-----------------------------------------
ms     %     Task name
-----------------------------------------
02517  047%  Initializing
02809  053%  Creating

3.1.2

Running org.springframework.issues.ReproTests
StopWatch 'Prototyped Bean Creation': running time (millis) = 36734
-----------------------------------------
ms     %     Task name
-----------------------------------------
00438  001%  Initializing
36296  099%  Creating

3.2.0.BUILD-SNAPSHOT (20120805.180303)

Running org.springframework.issues.ReproTests
StopWatch 'Prototyped Bean Creation': running time (millis) = 35807
-----------------------------------------
ms     %     Task name
-----------------------------------------
00433  001%  Initializing
35374  099%  Creating

@spring-projects-issues
Copy link
Collaborator Author

@spring-projects-issues spring-projects-issues commented Aug 30, 2012

Phil Webb commented

#131

3.0.7

StopWatch 'Prototyped Bean Creation': running time (millis) = 3719
-----------------------------------------
ms     %     Task name
-----------------------------------------
00589  016%  Initializing
03130  084%  Creating

3.2.0.BUILD-SNAPSHOT (before)

StopWatch 'Prototyped Bean Creation': running time (millis) = 42980
-----------------------------------------
ms     %     Task name
-----------------------------------------
00536  001%  Initializing
42444  099%  Creating

3.2.0.BUILD-SNAPSHOT (after)

StopWatch 'Prototyped Bean Creation': running time (millis) = 3980
-----------------------------------------
ms     %     Task name
-----------------------------------------
00445  011%  Initializing
03535  089%  Creating

@spring-projects-issues
Copy link
Collaborator Author

@spring-projects-issues spring-projects-issues commented Sep 7, 2012

Juergen Hoeller commented

A quick update since this is still in progress: I've gone into three different areas where optimization is due, two of which are related to argument caching not properly working - in particular, with String literal arguments of which there are quite a few in this repro test. A bad != check where we should check !equals breaks static String detection...

The good news: A !equals fix for String argument caching brings a radical improvement here, passing the test on 3.1.3 significantly faster than on 3.0.7. Of course, there is still room for improvement in 3.1's extensive argument conversion algorithm as suggested by Kevin and Phil; it just turns out to be less relevant once argument caching is fixed.

Juergen

@spring-projects-issues
Copy link
Collaborator Author

@spring-projects-issues spring-projects-issues commented Sep 7, 2012

Juergen Hoeller commented

This generally relates to #12081 where we deactivated the caching of converted constructor argument values in order to avoid a race condition. It looks like worth reactivating with the slightly reordered algorithm there in the meantime.

However, that code for #12081 does not actually make a big difference in the present test scenario since our broken String literal caching (as outlined above) is overwhelmingly the dominant factor here.

@spring-projects-issues
Copy link
Collaborator Author

@spring-projects-issues spring-projects-issues commented Sep 10, 2012

Juergen Hoeller commented

Marking this as resolved for the time being, with our expression detection properly handling cached String literals.

While there is still room for improvement, the regression can be considered as fixed since we even beat 3.0.7 on performance in such a scenario now.

Juergen

@spring-projects-issues
Copy link
Collaborator Author

@spring-projects-issues spring-projects-issues commented Aug 20, 2013

Jonatan Jönsson commented

Related to ReflectionUtils:
I've experimented with caching the results of ReflectionUtils#isObjectMethod(Method) (with Guava)


    public static boolean isObjectMethod(Method method) {
        return cache.getUnchecked(method);
    }

    private static final LoadingCache<Method, Boolean> cache = CacheBuilder
            .newBuilder().build(new CacheLoader<Method, Boolean>() {

                @Override
                public Boolean load(Method method) throws Exception {
                    try {
                        Object.class.getDeclaredMethod(method.getName(),
                                method.getParameterTypes());
                        return true;
                    } catch (SecurityException ex) {
                        return false;
                    } catch (NoSuchMethodException ex) {
                        return false;
                    }
                }
            });


public static void main(String[] args) throws IOException,
            SecurityException, NoSuchMethodException {
        //Warmup guava
        cache.getUnchecked(String.class.getDeclaredMethod("contains",
                new Class[] { CharSequence.class }));

        ClassPath path = ClassPath.from(Counter.class.getClassLoader());
        int nrOfMethods = 0;
        List<Method> methods = Lists.newArrayList();
        ImmutableSet<ClassInfo> classes = path.getTopLevelClasses();
        System.out.println("Classes: " + classes.size());

        for (ClassInfo o : classes) {
            for (Method m : o.getClass().getMethods()) {
                methods.add(m);
            }
        }
        System.out.println("Methods: " + methods.size());

        Stopwatch timer = new Stopwatch().start();
        for (Method m : methods) {
            if (cache.getUnchecked(m)) {
                // if (ReflectionUtils.isObjectMethod(m)) {
                nrOfMethods++;
            }
        }

        System.out.println("Object methods: " + nrOfMethods);
        System.out.println("Time: " + timer);
    }

In my experiments the old uncached version:
Classes: 32692
Methods: 490380
Object methods: 294228
Time: 1.002 s

Whereas my modified version:
Time: 102.9 ms

This means that with a code base with an average of 6 (non-object) methods per class you save 9 tenths time.

My reasoning is that when 2/3 of the calls can use the cache, it should cache. Especially when reflection is concerned.

If yoy're worried about the cache growing a simple Set of strings, guarding the more expensive lookups, like this:


private static final Set<String> objectMethodNames = buildMap();

    private static Set<String> buildMap() {
        ImmutableSet.Builder<String> methods = ImmutableSet.builder();
        for (Method m : Object.class.getDeclaredMethods()) {
            methods.add(m.getName());
        }
        return methods.build();
    }

    public static boolean isObjectMethodName(Method method) {
        if (objectMethodNames.contains(method.getName())
                && ReflectionUtils.isObjectMethod(method)) {
            return true;
        } else {
            return false;
        }
    }

Gives 1/3 better performance.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
in: core type: enhancement
Projects
None yet
Development

No branches or pull requests

2 participants