Digging into slow DAO creation

[Ian Dees]

Hi all,

We're seeing very long DAO creation times (several hundred milliseconds per DAO, 15 DAOs get created in 3-5 seconds) in our Android app that uses Ormlite.

With a bunch of tracing I see that DatabaseFieldConfig.fromDatabaseField() gets called to determine the database configuration while computing the TableConfig (TableConfig.fromClass()). The fromDatabaseField() method makes several calls to the DatabaseField annotation and in Android's VM it appears that those calls get passed through a dynamically-generated "annotation Proxy" [0] of some sort that does some excruciatingly-slow String manipulation to find the right Annotation method to invoke. This takes up 80% of the CPU time while creating the DAO.

I'm not sure what we can do to speed it up (other than not using annotations in Android).

Has anyone found a way to work around this?

[0] http://www.java2s.com/Open-Source/Android/android-core/platform-libcore/org/apache/harmony/lang/annotation/AnnotationFactory.java.htm

[Gray Watson]

Ok.  I have to respond quickly right now but this is great work Ian.  Thanks much for it.

I'll see if I can reproduce this enough to see if there is something Ormlite is doing wrong here.

Thanks again dude,

Gray

[Ian Dees]

I don't think ORMlite is doing anything wrong. I think it's a Dalvik-specific implementation problem (dynamic method invocation is S L O W in other cases, too).

The workaround we're trying is to create the DatabaseTableConfig manually/programmatically in our DAOs (to avoid the reflection). I imagine this will be quite a bit faster but a lot noisier code-wise.

[Gray Watson]

Holy cow! So I just did the following:

field = SomeClass.class.getDeclaredField("foo");
before = System.currentTimeMillis();
for (int i = 0; i < 100; i++) {
DatabaseFieldConfig.fromField(databaseType, getName(), field);
}
logger.info("DatabaseFieldConfig.fromField {} times in {} ms", NUM, (System.currentTimeMillis() - before));

I see TONS of GC activity and it took 2.3 SECONDS.

D/dalvikvm( 339): GC freed 6277 objects / 458640 bytes in 76ms
D/dalvikvm( 339): GC freed 9230 objects / 581664 bytes in 63ms
D/dalvikvm( 339): GC freed 8229 objects / 524688 bytes in 61ms
D/dalvikvm( 339): GC freed 8218 objects / 523848 bytes in 61ms
D/dalvikvm( 339): GC freed 8216 objects / 524096 bytes in 63ms
D/dalvikvm( 339): GC freed 8228 objects / 524648 bytes in 63ms
D/dalvikvm( 339): GC freed 8219 objects / 523928 bytes in 62ms
D/dalvikvm( 339): GC freed 8228 objects / 524624 bytes in 81ms
D/dalvikvm( 339): GC freed 8215 objects / 524448 bytes in 67ms
D/dalvikvm( 339): GC freed 8214 objects / 523568 bytes in 71ms
D/dalvikvm( 194): GC freed 109 objects / 4696 bytes in 276ms
D/dalvikvm( 339): GC freed 8230 objects / 524704 bytes in 76ms
I/AndroidAnnotationTest( 339): DatabaseFieldConfig.fromField 100 times in 2335 ms

I can see a bunch of things that we can do differently here. ORMLite could "compile" classes down to their DatabaseFieldConfig. The question is where to store this information.

More coming on this...
gray

[Gray Watson]

For everyone's info, I've posted the following to stackoverflow.com because it's a interesting question and worth broadcasting to the larger SE community:

http://stackoverflow.com/questions/7417426

gray

[Ian Dees]

When I was poking through there it looked like Dalvik created a Proxy object of some sort (via an AnnotationFactory) that used reflection to call the appropriate @interface methods on the Annotation object. If you look at AnnotationFactory's [0] invoke() helper method you can see that it loops through all the AnnotationMembers using .equals() calls to find the right one. Those .equals() [1] calls use String concatenation to build up a field identifier (basically the Java source code for that particular field) to make the comparison (when it's done with the .equals() that memory used by the Strings is garbage, thus all the GC you're seeing).

[0] http://www.java2s.com/Open-Source/Android/android-core/platform-libcore/org/apache/harmony/lang/annotation/AnnotationFactory.java.htm

[1] For example, see equals() here: http://www.java2s.com/Open-Source/Android/android-core/platform-libcore/java/lang/reflect/Method.java.htm

[Gray Watson]

Ok. Thanks to Ian's work, I did some more digging and it goes back to _gross_ code in Method.equals. Basically it is doing 2 StringBuilder with no good initializing size. Just awful code. Ok. So I'm looking into whether or not I can hack the proxy or include my own Method.class or something gross.

So I see a couple of things that ORMLite can do:

1) I'm playing around a bit with dividing up the @DatabaseField into a number of smaller annotations. A @DatabaseFieldSimple with 5 fields is an order of magnitude faster for example. @DatabaseField would still be supported.

2) I'm going to add some utility classes to take a database class with annotations and generate Java (or some other config) to configure the class in code. This seems like a very "by hand" solution so you'd have to make a change to your data class and then remember to update the config files before installing.

3) I'm wondering however if ORMLite could do some caching of these configs under the covers. It would mean generating some sort of config file either at installation time (best) or when the app is first run. This is out of my experience. Anyone have some idea here?

thanks,
gray

[Gray Watson]

> 1) I'm playing around a bit with dividing up the @DatabaseField into a number of smaller annotations. A @DatabaseFieldSimple with 5 fields is an order of magnitude faster for example. @DatabaseField would still be supported.

Ok. I've copied @DatabaseField and divided it up into: @DatabaseFieldSimple, @DatabaseFieldId, @DatabaseFieldForeign, @DatabaseFieldIndex, and @DatabaseFieldOther.

Work in progress here but that will give folks an option. Using just @DatabaseFieldSimple is significantly faster than @DatabaseField because there are fewer methods. How stupid is that.

> 2) I'm going to add some utility classes to take a database class with annotations and generate Java (or some other config) to configure the class in code. This seems like a very "by hand" solution so you'd have to make a change to your data class and then remember to update the config files before installing.

This has been completed. It's a bit of a hack so far. Basically you have a utility program in your project that has to be configured in Eclipse with the JRE in the build-path. It can either define a list of database classes in code or it can run through all of the Java files that it finds looking for @DatabaseTable or related annotations. It then generates a res/raw/ormlite_config.txt (or some other name) file which looks like:

#--table-start--
#9/14/11 6:49 PM
dataClass=com.example.helloandroid.SimpleData
tableName=simpledata
#--table-fields-start--
#--field-start--
#9/14/11 6:49 PM
fieldName=id
canBeNull=true
generatedId=true
persisterClass=com.j256.ormlite.field.types.VoidType
#--field-end--
...

Then in your DatabaseHelper you just do something like:

public DatabaseHelper(Context context) {
super(context, DATABASE_NAME, null, DATABASE_VERSION, R.raw.ormlite_config);
}

Notice the file-id at the end there. That will load the configs into the DaoManager so when you create a DAO it will not use the annotations. I can see a GC difference even if my little HelloAndroid program. Without the config file:

I/HelloAndroid( 470): creating class com.example.helloandroid.HelloAndroid
D/dalvikvm( 470): GC freed 6278 objects / 472656 bytes in 89ms
I/HelloAndroid( 470): deleting simple(26) returned 1
I/HelloAndroid( 470): deleting simple(27) returned 1
I/HelloAndroid( 470): created simple(1316039078384)
I/ActivityManager( 51): Displayed activity com.example.helloandroid/.HelloAndroid: 1176 ms (total 1176 ms)
D/dalvikvm( 190): GC freed 83 objects / 4008 bytes in 51ms
D/dalvikvm( 96): GC freed 3226 objects / 181792 bytes in 92ms

With the config file:

I/DaoManager( 436): Loaded class com.example.helloandroid.SimpleData from config
I/HelloAndroid( 436): creating class com.example.helloandroid.HelloAndroid
I/HelloAndroid( 436): deleting simple(23) returned 1
I/HelloAndroid( 436): deleting simple(24) returned 1
I/HelloAndroid( 436): deleting simple(25) returned 1
I/HelloAndroid( 436): created simple(1316039017942)
I/HelloAndroid( 436): created simple(1316039017973)
I/ActivityManager( 51): Displayed activity com.example.helloandroid/.HelloAndroid: 1101 ms (total 1101 ms)
-- no gc activity afterwards

WARNING: The worry here is that you might _forget_ to generate the config file before you run your program or (heaven help us) release it.

Thoughts? Should I push a beta version?
gray

[Ian Dees]

Personally, I really like your option #2. Since our databases are pre-generated (Ormlite is used to make queries easier) we can generate the config files at the same time we generate the databases.

I'd be happy to test the utility program piece and a beta if you'd like to shoot it my way.

[Craig Andrews]

1) I don't like this one. Long after the Android slowness bug is fixed,
ORMLite will have to carry around the baggage of these extra annotations
and all the complications they cause. This approach seems too costly for
the long time maintenance of ORMLite.

2) This approach I like. IMHO, as long as you document how to integrate
with Ant and Maven, this should work nicely. Of course, without the
Ant/Maven integration instructions, I bet your concerns that developers
won't keep the compiled definitions updated will be validated.

I personally can't wait to implement option 2 in my project :-)

Thanks!
~Craig

BTW - I find it amusing that 2 bugs which have annoyed me for a couple of
months, slow annotation introspection and early freed SoftReferences,
ended up being related and came to head in ORMLite on the same day.

[Gray Watson]

I've updated the 4.26beta version with the new code with the database config file code.

http://ormlite.com/releases/

To get it to work you'll need to:

1) Create a DatabaseUtil.java class alongside your data classes. Something like this:

public class DatabaseUtil extends OrmLiteConfigUtil {
public static void main(String[] args) throws Exception {
writeConfigFile("ormlite_config.txt");
}
}

2) You'll need to run this with the Java JRE on your development box. I did this under Eclipse by selecting it, pulling down the run button to run configurations. For the DatabaseUtil choose the JRE tab and then alternate JRE since the default is none.

3) When you run the utility it will look for the res directory above the code and then find the raw sub-directory under res. You'll need to create it if it doesn't exist. It should write the filename specified in the above main into res/raw. It will look like:

# generated on 2011/09/15 01:40:10
# --table-start--
dataClass=com.example.helloandroid.SimpleData
tableName=simpledata
...

4) Then change your helper to use the constructor with the file-id:

public DatabaseHelper(Context context) {
super(context, DATABASE_NAME, null, DATABASE_VERSION, R.raw.ormlite_config);
}

The R.java file should have been auto-generated when you refresh the project and it sees the res/raw/ormlite_config.txt. The name of the variable needs to match the filename above.

5) After building and installing your application, you'll know if its working if you see something like the following in the adb logs:

I/DaoManager( 999): Loaded configuration for class com.example.helloandroid.SimpleData

Sorry but the documentation is pretty weak at this point. Take a look at the HelloAndroid program to see it in action:

http://ormlite.svn.sourceforge.net/viewvc/ormlite/examples/android/HelloAndroid/

Feedback please,
gray

[Craig Andrews]

If you could make OrmLiteConfigUtil have a main method itself that takes
the filename as an argument, then we could use the exec-maven-plugin to
build the raw resource before the compile phase. Such a block could look
like this:
<build>
<plugins>
<plugin>
<groupId>org.codehaus.mojo</groupId>
<artifactId>exec-maven-plugin</artifactId>
<executions>
<execution>
<phase>process-resources</phase>
<goals>
<goal>java</goal>
</goals>
<configuration>
<mainClass>com.j256.ormlite.android.apptools.OrmLiteConfigUtil</mainClass>
<arguments>
<argument>ormlite_config.txt</argument>
</arguments>
</configuration>
</execution>
</executions>
</plugin>
</plugins>
</build>

Actually, now that I think about it... the ORMLite config file requires
the Java source to be compiled, but the Java source can't be compiled
until the ORMLite config file exists (otherwise R.raw.ormlite_config
doesn't exist). How do you get around this catch-22?

Thanks,
~Craig

[Craig Andrews]

A simple solution just occurred to me. If, instead of using Android's
resources concept, you simply read a text file (instead of a resource) in
OrmLiteSqliteOpenHelper, and adjust the constructor accordingly to take a
String (for the text file's name/path) instead of a resource id, the
catch-22 (needing the config file to build the classes but needing the
classes to build the config file) goes away.

~Craig

[Gray Watson]

> Actually, now that I think about it... the ORMLite config file requires
> the Java source to be compiled, but the Java source can't be compiled
> until the ORMLite config file exists (otherwise R.raw.ormlite_config
> doesn't exist). How do you get around this catch-22?

THe first time you create the config file is when R.java needs to be updated. Any subsequent time when you are just regenerating the file, R.java does not change. No catch-22.

The problems are all around remembering to update the file after your touch your database classes.
gray

[Craig Andrews]

Thanks for the clarifications... that's not how I thought the R file
worked. I apologize for the trouble!

In order to ensure that developers don't forget to regenerate the ORMLite
config, I'd like to make it so they can't forget by excluding the file
from source control. Therefore, on the initial compile, the
R.raw.ormlite_config reference won't resolve... so could you make a
constructor that takes a String or InputStream or something else like that
so I could reference the config as a file instead of as an Android
resource?

[Gray Watson]

On Sep 14, 2011, at 11:51 PM, Craig Andrews wrote:

> 1) I don't like this one. Long after the Android slowness bug is fixed,
> ORMLite will have to carry around the baggage of these extra annotations
> and all the complications they cause. This approach seems too costly for
> the long time maintenance of ORMLite.

Well they cost only in terms of code only like 3k but I understand what you are talking about. The issue I see is that the Android bug isn't going to be fixed for a year at least and even then it won't support current devices. These smaller annotations will actually make a pretty significant difference -- 2500ms to 350ms in one of my tests. If I want to deprecate them later then fine but the support for them is minimal and confined to the DatabaseFieldConfig class.

> BTW - I find it amusing that 2 bugs which have annoyed me for a couple of
> months, slow annotation introspection and early freed SoftReferences,
> ended up being related and came to head in ORMLite on the same day.

Heh. I'm not sure SoftReferences have anything to do with the Method.equals() being dog slow. I think it just shows that the Android code base has got some gross sections in it. Not surprising I guess but still disappointing.

gray

[Gray Watson]

So here are some quick performance numbers from DAO creation in HelloAndroid. I duplicated the SimpleData class a bunch of times and timed the startup and totaled the GC numbers.

10 DAOs:
@DatabaseField: 1331ms startup. GC: 43,k objs, 2.8mb, 431ms
@DatabaseFieldSimple (and friends): 806ms startup, GC: 21k obis, 1.2mb, 285ms
ormlite_config.txt loaded: 283ms startup, GC: none reported

20 DAOs:
@DatabaseField: 2408ms startup. GC: 81k objs, 5.2mb, 431ms
@DatabaseFieldSimple (and friends): 1239ms startup, GC: 37k obis, 2.1mb, 310ms
ormlite_config.txt loaded: 433ms startup, GC: 5k objs, 354kb, 94ms

So this is certainly an improvement.
gray