Performance problem or wrong usage?

[GoogleCodeExporter]

Hello,
this is my first contact mit DI and Guice.
I have a question about the performance from Guice.

The following small JUnit is creating some object with Guice
and by a own factory implementation.

If I measure the object creation (and some setters), Guice is 
up to 50 times slower then the own code.

Do I use Guice in a wrong way or is the performance as bad as I have measured?

Uwe
-----
package sandbox.guice.performance;

import static org.junit.Assert.*;
import org.junit.After;
import org.junit.AfterClass;
import org.junit.Before;
import org.junit.BeforeClass;
import org.junit.Test;

import com.google.inject.Binder;
import com.google.inject.Guice;
import com.google.inject.Injector;
import com.google.inject.Module;

public class PerfTest {

    static private final int max = 1000000;

    @BeforeClass
    public static void setUpBeforeClass() throws Exception {
    }

    @AfterClass
    public static void tearDownAfterClass() throws Exception {
    }

    @Before
    public void setUp() throws Exception {
    }

    @After
    public void tearDown() throws Exception {
    }

    static interface Person {

        public abstract String getFirstName();

        public abstract void setFirstName(String firstName);

        public abstract String getLastName();

        public abstract void setLastName(String lastName);

    }

    static class RealPerson implements Person {
        private String firstName;
        private String lastName;
        @Override
        public String getFirstName() {
            return firstName;
        }
        @Override
        public void setFirstName(String firstName) {
            this.firstName = firstName;
        }
        @Override
        public String getLastName() {
            return lastName;
        }
        @Override
        public void setLastName(String lastName) {
            this.lastName = lastName;
        }

    }

    static abstract class PersonFactory {
        static Person createPerson() {return new RealPerson();}
    }

    @Test
    public void testClassicWay () throws Exception {
        long t1 = System.currentTimeMillis();
        for (int i = 0; i < max; i++) {
            Person person = PersonFactory.createPerson();
//          person.setFirstName("Guice");
//          person.setLastName("Google");
//          
//          assertEquals(RealPerson.class, person.getClass());
//          assertEquals("Guice" , person.getFirstName());
//          assertEquals("Google", person.getLastName());
        }
        long t2 = System.currentTimeMillis();
        System.out.format("%-20s %6d %5dms\n", "ClassicWay", max, (t2-t1));
    }

    @Test
    public void testGuiceSimple () throws Exception {
        Injector injector = Guice.createInjector(new Module() {
            @Override
            public void configure(Binder binder) {
                binder.bind(Person.class).to(RealPerson.class);
            }
        });

        long t1 = System.currentTimeMillis();
        for (int i = 0; i < max; i++) {
            Person person = injector.getInstance(Person.class);
//          person.setFirstName("Guice");
//          person.setLastName("Google");
//          
//          assertEquals(RealPerson.class, person.getClass());
//          assertEquals("Guice" , person.getFirstName());
//          assertEquals("Google", person.getLastName());
        }
        long t2 = System.currentTimeMillis();
        System.out.format("%-20s %6d %5dms\n", "GuiceSimple", max, (t2-t1));
    }
}

Original issue reported on code.google.com by ula.uvula@gmx.de on 11 Nov 2010 at 11:47

[GoogleCodeExporter]

Please read: http://www.ibm.com/developerworks/java/library/j-jtp02225.html

It's hard to write a good benchmark - for example in your code the Person 
object is never used, and because the simple PersonFactory is a private static 
class with a one-line method that just calls new the JIT could be unrolling 
that method. It would then see that there's no side-effect and so the call can 
safely be removed (ie. dead-code optimization) making it a very fast loop. The 
Guice call however involves more method calls making it unlikely the JIT would 
inline it or decide that the call could be omitted. Other issues with your code 
include no JIT warmup, no guards against GC disturbing the timing, and using 
coarse millisecond timing.

Talking about multiples is also misleading: say 'new' took 1ns and guice took 
50ns then while that's still a multiple of 50, it might not lead to a 
noticeable slowdown in your application - it would all depend on how many 
objects you were creating via Guice.

Obviously Guice will always be slower than pure "new" when constructing 
objects, because that's only a few opcodes compared to all the reflection and 
management required to analyze the class, find its dependencies, and inject 
them. The question is whether this makes a noticeable difference for a sizeable 
application. Even then it's not a straight comparison because while manual 
wiring may be fast, it's also very fragile and fixed - whereas good dependency 
injection is flexible and configurable. Another point to consider is that 
injection is typically an up-front cost: once your application is wired 
together it will perform exactly the same as if you used manual wiring.

So to sum up: don't worry about micro-benchmarks, much better to test against 
real-world applications.

Original comment by mccu...@gmail.com on 12 Nov 2010 at 12:17

[GoogleCodeExporter]

Hello Mcculls,
thanks for the quick response (sorry, my english is not the best, but I hope 
you can understand).

- I see: I'm not only a beginner with DI/Guice, also in Java.
- I was aware, that my test (with all the commented lines (//)) only measure 
the creation time of a object.
  And the a compiler can optimize many things (drop unused object etc).
  I was not aware about the JIT optimization, which maybe infects the measurements.
- I was aware, that Guice must be slower than pure "new" operations and uses 
"reflection".
- As longer I use an object the lesser the overhead of the creation is.
- So you are right: I must see both, the creation and the usage of an object.
- I was aware, after the "wiring", the rest of the code has the same 
performance (usage of the object).
- I agree now: I can't see the creation isolated from the usage.

My second test (see below - I'm sure this test is not perfect) will do now some 
more steps
with the created person, so the person will be used (getter/setter). (Plus 
other stuff like string concatination).

- Now the ratio between creation/usage is much better
- Now the ratio between the classic way and Guice is much better and the 
overhead is acceptable.
- I don't worry about an application is 10% - 50% slower, but 50 times is too 
much, so I was confused

Here the result from the test:
(Measurement is now in nanosec, only the output is in millisec)

T = totalTime
C = creationTime (accumulated)
U = usageTime    (accumulated)
testClassicWay       Iter: 1000000 C: 1225ms U: 2182ms T: 5863ms C/U 0,562 C/T: 
0,209
testGuiceSimple      Iter: 1000000 C: 2086ms U: 2125ms T: 6614ms C/U 0,981 C/T: 
0,315
Classic/Guice: 0,887 - Guice/Classic: 1,128
Person Instances created: 2000000

Thanks for your help, I will give Guice now a chance :-)

Uwe

---
package sandbox.guice.performance;

import static org.junit.Assert.*;
import org.junit.After;
import org.junit.AfterClass;
import org.junit.Before;
import org.junit.BeforeClass;
import org.junit.Test;

import com.google.inject.Binder;
import com.google.inject.Guice;
import com.google.inject.Injector;
import com.google.inject.Module;
import com.google.inject.internal.cglib.proxy.Factory;

public class PerfTest {

    static private final long max = 1000000;
    static private long testClassicWay  = 0;
    static private long testGuiceSimple = 0;

    @BeforeClass
    public static void setUpBeforeClass() throws Exception {
        System.out.println("T = totalTime");
        System.out.println("C = creationTime (accumulated)");
        System.out.println("U = usageTime    (accumulated)");
    }

    @AfterClass
    public static void tearDownAfterClass() throws Exception {
        System.out.format("Classic/Guice: %s - Guice/Classic: %s\n", factor(testClassicWay, testGuiceSimple), factor(testGuiceSimple, testClassicWay));
        System.out.println("Person Instances created: " + RealPerson.personInstances);
        assertEquals(max * 2, RealPerson.personInstances);
    }

    @Before
    public void setUp() throws Exception {
    }

    @After
    public void tearDown() throws Exception {
    }

    static interface Person {
        public abstract String getFirstName();
        public abstract void setFirstName(String firstName);
        public abstract String getLastName();
        public abstract void setLastName(String lastName);
    }

    static class RealPerson implements Person {
        static int personInstances = 0;  // to see, that person is really created
        private String firstName;
        private String lastName;
        public RealPerson () {
            personInstances++;
        }
        @Override
        public String getFirstName() {
            return firstName;
        }
        @Override
        public void setFirstName(String firstName) {
            this.firstName = firstName;
        }
        @Override
        public String getLastName() {
            return lastName;
        }
        @Override
        public void setLastName(String lastName) {
            this.lastName = lastName;
        }
    }

    static abstract class PersonFactory {
        public static Person createPerson() {return new RealPerson();}
    }

    static abstract class PersonFactoryWrapperToBeMoreExpensiveForTheClassicWay extends PersonFactory {
        public static Person createPerson() {return PersonFactory.createPerson();}
    }

    static private String time (long t) {
        return "" + (t / 1000000) + "ms";
    }

    static private String factor(double a, double b) {
        return String.format("%.3f", a / b);
    }

    public void usePerson (Person person, long i) throws Exception {
        person.setFirstName("Guice" +i);
        person.setLastName("Google" +i);
        assertEquals(RealPerson.class, person.getClass());
        assertEquals("Guice"  +i, person.getFirstName());
        assertEquals("Google" +i, person.getLastName());
    }

    @Test
    public void testClassicWay () throws Exception {
        long t1 = System.nanoTime();
        long creationTime = 0;
        long usageTime = 0;
        for (long i = 0; i < max; i++) {
            long c1, c2;
            c1 = System.nanoTime();
            Person person = PersonFactoryWrapperToBeMoreExpensiveForTheClassicWay.createPerson();
            c2 = System.nanoTime();
            creationTime += c2 - c1;
            c1 = System.nanoTime();
            usePerson(person, i);
            c2 = System.nanoTime();
            usageTime += (c2 - c1);
        }
        long t2 = System.nanoTime();
        long totalTime = t2 - t1;
        testClassicWay = totalTime;
        System.out.format("%-20s Iter: %6d C: %s U: %s T: %s C/U %s C/T: %s\n", 
                Thread.currentThread().getStackTrace()[1].getMethodName(), max,
                time(creationTime), time(usageTime), time(t2-t1), factor (creationTime, usageTime), factor (creationTime, totalTime));
    }

    @Test
    public void testGuiceSimple () throws Exception {
        Injector injector = Guice.createInjector(new Module() {
            @Override
            public void configure(Binder binder) {
                binder.bind(Person.class).to(RealPerson.class);
            }
        });

        long t1 = System.nanoTime();
        long creationTime = 0;
        long usageTime = 0;
        for (long i = 0; i < max; i++) {
            long c1, c2;
            c1 = System.nanoTime();
            Person person = injector.getInstance(Person.class);
            c2 = System.nanoTime();
            creationTime += c2 - c1;
            c1 = System.nanoTime();
            usePerson(person, i);
            c2 = System.nanoTime();
            usageTime += (c2 - c1);
        }
        long t2 = System.nanoTime();
        long totalTime = t2 - t1;
        testGuiceSimple = totalTime;
        System.out.format("%-20s Iter: %6d C: %s U: %s T: %s C/U %s C/T: %s\n", 
                Thread.currentThread().getStackTrace()[1].getMethodName(), max,
                time(creationTime), time(usageTime), time(t2-t1), factor (creationTime, usageTime), factor (creationTime, totalTime));
    }
}

Original comment by ula.uvula@gmx.de on 12 Nov 2010 at 12:01

[GoogleCodeExporter]

Original comment by sberlin on 12 Nov 2010 at 12:45

• Changed state: Invalid

[GoogleCodeExporter]

@Uwe

Unless your creating/obtaining zillions of objects from Guice why does it 
matter if its 50x or 500x slower. In the end that micro micro second doesnt 
really matter if the productivity gained from Guice dramatically helps you 
reach your goal. Cpu cycles are cheap compared to your time.

Original comment by miroslav...@gmail.com on 22 Mar 2011 at 4:52