Manual Coercion Performance Seems Pretty Bad #96

Open
codeconsole opened this Issue Nov 23, 2011 · 28 comments

Projects

None yet

4 participants

@codeconsole
Contributor

Manual coercion seems to be performing pretty bad.

Example:

import com.google.appengine.api.datastore.Entity
import groovyx.gaelyk.GaelykCategory
import org.springframework.util.StopWatch
import groovyx.gaelyk.datastore.Key
import groovy.transform.Canonical

def watch = new StopWatch("Coercion")

@Canonical
class Person {
  @Key Long id
  String name
}

use (GaelykCategory) {
  watch.start("build")
  def entities = []
  for (long i = 1; i < 200; i++) {
    Entity entity = new Entity("Person", i)
    entity.name = "Person ${i}"
    entities << entity
  }  
  watch.stop()
  watch.start("manual coercion")
  entities.each {
    it as Person
  } 
  watch.stop()
  watch.start("construction")
  entities.each {
    new Person(it.id, it.name)
  }   
  watch.stop()
  System.out.println watch.toString()
}

result:

StopWatch 'Coercion': running time (millis) = 576; [build] took 20 = 3%; [manual coercion] took 530 = 92%; [construction] took 26 = 5%

@codeconsole
Contributor

What do you think can be done to improve the performance?

Creating as asType for a List?

@codeconsole
Contributor

More tests:

import com.google.appengine.api.datastore.Entity
import groovyx.gaelyk.GaelykCategory
import org.springframework.util.StopWatch
import groovyx.gaelyk.datastore.Key
import groovy.transform.Canonical
import groovyx.gaelyk.datastore.PogoEntityCoercion

def watch = new StopWatch("Coercion")

@Canonical
class Person {
  @Key Long id
  String name
}

class OldCategory {
    static Object asType(Entity self, Class clazz) {
        return clazz.newInstance(self.properties)
    }
}

class OldCheckCategory {
    static Object asType(Entity self, Class clazz) {
        def entityProps = self.getProperties()

        def o = clazz.newInstance()
        entityProps.each { k, v ->
            if (o.metaClass.hasProperty(o, k)) {  
                o[k] = v
            }
        }      
        return o
    }
}


class NewCategory {
    static Object asType(Entity self, Class clazz) {
        def entityProps = self.getProperties()

        def o = clazz.newInstance()
        entityProps.each { k, v ->
            if (o.metaClass.hasProperty(o, k)) {  
                o[k] = v
            }
        }
        PogoEntityCoercion.props(o)
        return o
    }
}

use (GaelykCategory) {
  watch.start("build")
  def entities = []
  for (long i = 1; i < 200; i++) {
    Entity entity = new Entity("Person", i)
    entity.name = "Person ${i}"
    entities << entity
  }  
  watch.stop()
  watch.start("manual coercion")
  entities.each {
    it as Person
  } 
  watch.stop()
  watch.start("construction")
  entities.each {
    new Person(it.id, it.name)
  }   
  use (OldCategory) {
    watch.stop()
    watch.start("old coercion")
    entities.each {
      it as Person
    } 
  }
  use (OldCheckCategory) {
    watch.stop()
    watch.start("old checked coercion")
    entities.each {
      it as Person
    } 
  } 
  use (NewCategory) {
    watch.stop()
    watch.start("PogoEntityCoercion.props")
    entities.each {
      it as Person
    } 
  }   
  watch.stop()
  System.out.println watch.toString()
}

StopWatch 'Coercion': running time (millis) = 1112; [build] took 13 = 1%; [manual coercion] took 470 = 42%; [construction] took 56 = 5%; [old coercion] took 19 = 2%; [old checked coercion] took 39 = 4%; [PogoEntityCoercion.props] took 515 = 46%

@codeconsole
Contributor

Looks like the slowness comes from PogoEntityCoercion.props
Is there any way to cache the results of PogoEntityCoercion.props?

@glaforge
Contributor

What's costly is indeed the reflection that I've had to add for checking the annotation presence -- ie. your fault ;-)
Since this "metadata" is not going to change once the application is deployed, we could probably let the PogoEntityCoercion class have some static field that would hold a Map associating the class name and the "props".
I'm usually not fond of static fields (except for constants), but in that case, I think it's okay.

@glaforge glaforge closed this in 44346d4 Nov 27, 2011
@glaforge
Contributor

Could you please try the latest version on github?
On my own little tests, the coercion is now more than twice as fast.

@codeconsole
Contributor

Sure, I will run some tests later today.

@codeconsole
Contributor

MUCH BETTER, 80 ms now vs 530 ms before
I think the extra 50 ms is acceptable.

StopWatch 'Coercion': running time (millis) = 200; [build] took 16 = 8%; [manual coercion] took 80 = 40%; [construction] took 23 = 11%; [old coercion] took 23 = 11%; [old checked coercion] took 29 = 15%; [PogoEntityCoercion.props] took 29 = 15%

@glaforge
Contributor

Excellent, good to know!
Thanks for running your benchmark.

@codeconsole
Contributor

Bizarre, I go this out of the blue today from 1 instance (I typically have about 14 running).

java.security.AccessControlException: access denied (java.lang.RuntimePermission accessDeclaredMembers)

It happened almost of every request by that instance while the other instances processed similar requests flawlessly and the entire app ran flawlessly for 22 hours.

What do yo make of it?

java.security.AccessControlException: access denied (java.lang.RuntimePermission accessDeclaredMembers)
at java.security.AccessControlContext.checkPermission(AccessControlContext.java:355)
at java.security.AccessController.checkPermission(AccessController.java:567)
at java.lang.SecurityManager.checkPermission(SecurityManager.java:549)
at java.lang.reflect.Method.invoke(Method.java:43)
at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
at org.codehaus.groovy.runtime.callsite.StaticMetaMethodSite.invoke(StaticMetaMethodSite.java:43)
at org.codehaus.groovy.runtime.callsite.StaticMetaMethodSite.call(StaticMetaMethodSite.java:88)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:42)
at org.codehaus.groovy.runtime.callsite.StaticMetaMethodSite.call(StaticMetaMethodSite.java:93)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:116)
at groovyx.gaelyk.datastore.PogoEntityCoercion$_props_closure2.doCall(PogoEntityCoercion.groovy:34)

http://code.google.com/p/googleappengine/issues/detail?id=6433

@codeconsole
Contributor

It occurred on this line (PogoEntityCoercion.groovy:34):

                annos = p.class.getDeclaredMethod("get${k.capitalize()}").annotations
@codeconsole
Contributor

Random Google Bug??? I had to deploy a new version just to kill off the instance.

@glaforge
Contributor

This is quite mysterious.
GAE has a pretty strict and customized VM with stronger access control checks.
We've had to fight a few of them in the Groovy code base.
In this case, the offending line is just doing normal reflection, nothing particularly fancy or esoteric, so I don't see what could be wrong here. So it's perhaps indeed a "Random Google Bug"!
Perhaps you could show me what the original POGO looked like?

@codeconsole
Contributor

I am waiting for it to happen again:

            try {
                annos = p.class.getDeclaredField(k).annotations
            } catch (e) {
                if (e instanceof SecurityException) {
                    log.severe("COERCION ${e.toString()}: for ${clazz.name} field ${k}")
                }
                try {
                    annos = p.class.getDeclaredMethod("get${k.capitalize()}").annotations
                } catch (e2) {
                    log.severe("COERCION2 ${e.toString()}/${e2.toString()}: for ${clazz.name} field get${k.capitalize()}")
                }
            }
@codeconsole
Contributor

Uh oh, looks like coercion performance went down the drain again

 StopWatch 'Coercion': running time (millis) = 695; [build] took 8 = 1%; [manual coercion] took 596 = 86%; [construction] took 91 = 13%
 StopWatch 'Coercion': running time (millis) = 604; [build] took 100 = 17%; [manual coercion] took 419 = 69%; [construction] took 85 = 14%
 StopWatch 'Coercion': running time (millis) = 497; [build] took 11 = 2%; [manual coercion] took 304 = 61%; [construction] took 182 = 37%
 StopWatch 'Coercion': running time (millis) = 364; [build] took 73 = 20%; [manual coercion] took 200 = 55%; [construction] took 91 = 25%
 StopWatch 'Coercion': running time (millis) = 366; [build] took 64 = 17%; [manual coercion] took 227 = 62%; [construction] took 75 = 20%

I ran this code 5 times and the best I could do was 200ms

 import com.google.appengine.api.datastore.Entity

 import org.springframework.util.StopWatch
 import groovyx.gaelyk.datastore.Key
 import groovy.transform.Canonical
 import groovyx.gaelyk.datastore.PogoEntityCoercion

 def watch = new StopWatch("Coercion")

 @Canonical
 class Person {
   @Key Long id
   String name
 }





   watch.start("build")
   def entities = []
   for (long i = 1; i < 200; i++) {
     Entity entity = new Entity("Person", i)
     entity.name = "Person ${i}"
     entities << entity
   }  
   watch.stop()
   watch.start("manual coercion")
   entities.each {
     it as Person
   } 
   watch.stop()
   watch.start("construction")
   entities.each {
     new Person(it.id, it.name)
   }   

   watch.stop()
   System.out.println watch.toString()
@codeconsole codeconsole reopened this Feb 7, 2013
@glaforge
Contributor
glaforge commented Feb 7, 2013

Nobody's touched to the coercion in a long while.
Did it really "slow down"? I wonder how that could be :-(
Is it happening with a newer version of Groovy vs an older one?

@musketyr musketyr added a commit that referenced this issue Feb 9, 2013
@musketyr musketyr tuned up pogo coerction #96 bbfa300
@musketyr
Contributor
musketyr commented Feb 9, 2013

@codeconsole please give a try to latest 2.0-SNAPSHOT - build versioin 45 or later, I've rewrite it a lot so I wonder what's the difference

@pixoto
Contributor
pixoto commented Feb 12, 2013

Ran 4 times with latest Gaelyk and Groovy 2.1.0:

StopWatch 'Coercion': running time (millis) = 498; [build] took 92 = 18%; [manual coercion] took 393 = 79%; [construction] took 13 = 3%
StopWatch 'Coercion': running time (millis) = 358; [build] took 8 = 2%; [manual coercion] took 259 = 72%; [construction] took 91 = 25%
StopWatch 'Coercion': running time (millis) = 182; [build] took 9 = 5%; [manual coercion] took 103 = 57%; [construction] took 70 = 38%
StopWatch 'Coercion': running time (millis) = 465; [build] took 69 = 15%; [manual coercion] took 304 = 65%; [construction] took 92 = 20%
@glaforge
Contributor

So is it good or bad?

@musketyr
Contributor

not sure either, but the best one is cca 100 ms which should be 50 % cut.

@pixoto
Contributor
pixoto commented Feb 12, 2013

Well, I think you got to look at average case... which still seems pretty bad

@musketyr
Contributor

don't have much ideas how to speed it up. any suggestions?

@pixoto
Contributor
pixoto commented Feb 12, 2013

I don't know, @glaforge do you think it has to do with all the app engine permission checks? can we circumvent by rewriting part of this in pure Java?

@musketyr
Contributor

there a few things to improve. e.g. we should now be finding the key and versions each time. I'll have a look a little more next time.

@musketyr
Contributor

@codeconsole I've added new DatastoreEntity interface, could you make your test class implement this interface and let me know if it works better?

37477c4

@codeconsole
Contributor

Unfortunately, this is after the 1.7.5 release w/ Java 7 and invoke dynamic (not sure if that had any impact as well), but it appears to have improved.

 StopWatch 'Coercion': running time (millis) = 203; [build] took 8 = 4%; [manual coercion] took 182 = 90%; [construction] took 13 = 6%
 StopWatch 'Coercion': running time (millis) = 203; [build] took 76 = 37%; [manual coercion] took 118 = 58%; [construction] took 9 = 4%
 StopWatch 'Coercion': running time (millis) = 282; [build] took 80 = 28%; [manual coercion] took 115 = 41%; [construction] took 87 = 31%
 StopWatch 'Coercion': running time (millis) = 189; [build] took 7 = 4%; [manual coercion] took 175 = 93%; [construction] took 7 = 4%
 StopWatch 'Coercion': running time (millis) = 209; [build] took 9 = 4%; [manual coercion] took 192 = 92%; [construction] took 8 = 4%
@codeconsole
Contributor

hmm, but actually construction dramatically improved as well, so then it is very difficult to say.

@musketyr
Contributor

From latest build (106) using (@Entity annotation)

StopWatch 'Coercion': running time (millis) = 176; [build] took 6 = 3%; [manual coercion] took 91 = 52%; [construction] took 79 = 45%
StopWatch 'Coercion': running time (millis) = 105; [build] took 5 = 5%; [manual coercion] took 18 = 17%; [construction] took 82 = 78%
StopWatch 'Coercion': running time (millis) = 102; [build] took 8 = 8%; [manual coercion] took 87 = 85%; [construction] took 7 = 7%
StopWatch 'Coercion': running time (millis) = 97; [build] took 5 = 5%; [manual coercion] took 15 = 15%; [construction] took 77 = 79%
StopWatch 'Coercion': running time (millis) = 98; [build] took 6 = 6%; [manual coercion] took 16 = 16%; [construction] took 76 = 78%
StopWatch 'Coercion': running time (millis) = 110; [build] took 11 = 10%; [manual coercion] took 90 = 82%; [construction] took 9 = 8%
StopWatch 'Coercion': running time (millis) = 104; [build] took 7 = 7%; [manual coercion] took 88 = 85%; [construction] took 9 = 9%
StopWatch 'Coercion': running time (millis) = 110; [build] took 7 = 6%; [manual coercion] took 93 = 85%; [construction] took 10 = 9%
StopWatch 'Coercion': running time (millis) = 99; [build] took 77 = 78%; [manual coercion] took 15 = 15%; [construction] took 7 = 7%
StopWatch 'Coercion': running time (millis) = 180; [build] took 75 = 42%; [manual coercion] took 27 = 15%; [construction] took 78 = 43%
@musketyr
Contributor

but you need to pay attention of using @Version annotation, with the version property you get following

StopWatch 'Coercion': running time (millis) = 2202; [build] took 85 = 4%; [manual coercion] took 2100 = 95%; [construction] took 17 = 1%
StopWatch 'Coercion': running time (millis) = 1678; [build] took 73 = 4%; [manual coercion] took 1561 = 93%; [construction] took 44 = 3%
StopWatch 'Coercion': running time (millis) = 1997; [build] took 12 = 1%; [manual coercion] took 1976 = 99%; [construction] took 9 = 0%
StopWatch 'Coercion': running time (millis) = 1349; [build] took 9 = 1%; [manual coercion] took 1330 = 99%; [construction] took 10 = 1%
StopWatch 'Coercion': running time (millis) = 1347; [build] took 8 = 1%; [manual coercion] took 1282 = 95%; [construction] took 57 = 4%
StopWatch 'Coercion': running time (millis) = 1401; [build] took 11 = 1%; [manual coercion] took 1368 = 98%; [construction] took 22 = 2%
StopWatch 'Coercion': running time (millis) = 3103; [build] took 14 = 0%; [manual coercion] took 3080 = 99%; [construction] took 9 = 0%
StopWatch 'Coercion': running time (millis) = 1693; [build] took 8 = 0%; [manual coercion] took 1676 = 99%; [construction] took 9 = 1%
StopWatch 'Coercion': running time (millis) = 1289; [build] took 7 = 1%; [manual coercion] took 1274 = 99%; [construction] took 8 = 1%
StopWatch 'Coercion': running time (millis) = 1149; [build] took 6 = 1%; [manual coercion] took 1135 = 99%; [construction] took 8 = 1%
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment