Some raw log data. I’m gonna go after the “Creating FormDef” 11.5 seconds now.
FormLoaderTask: Attempting to load eIMCI by D Tree.xml from cached file: /storage/emulated/0/odk/.cache/93d49a83bdfe2b842c6b23d0cc9e3cc0.formdef.
FormLoaderTask: Loaded in 6.020 seconds.
FormLoaderTask: Initializing form.
System.out: Nodes: 457, total string length: 11065
System.out: getLocaleData finished in 743.805 ms
FormLoaderTask: Form initialized in 3.104 seconds.
FormEntryActivity: calling formController.setLanguage
FormEntryActivity: Ended up with a bad language. null
System.out: PrefixTree 129383576 clearing
System.out: Nodes: 457, total string length: 11065
System.out: getLocaleData finished in 662.262 ms
FormLoaderTask: Attempting to load from: /storage/emulated/0/odk/forms/eIMCI by D Tree.xml
System.out: Parsing form...
System.out: Reading XML and parsing with kXML2 finished in 533.783 ms
System.out: Consolidating text finished in 455.505 ms
System.out: Title: "eIMCI by D-Tree"
System.out: Nodes: 798, total string length: 20473
System.out: getLocaleData finished in 1108.704 ms
System.out: Creating FormDef from parsed XML finished in 11,539.581 ms
FormLoaderTask: Loaded in 12.579 seconds. Now saving to cache.
FormLoaderTask: Saved in 11.475 seconds.
FormLoaderTask: Initializing form.
System.out: Nodes: 457, total string length: 11065
System.out: getLocaleData finished in 674.957 ms
FormLoaderTask: Form initialized in 3.211 seconds.
FormEntryActivity: calling formController.setLanguage
FormEntryActivity: Ended up with a bad language. null
System.out: PrefixTree 130682409 clearing
System.out: Nodes: 457, total string length: 11065
System.out: getLocaleData finished in 671.600 ms
FormEntryActivity: Done in 0.673 seconds.
@dcbriccetti Am I understanding correctly that on a Nexus 7 removing string prefixing gives a 706x speedup for the Nigeria Wards form with only 8-10mb of RAM (~12%) more? It would then load in less than a second? If that's correct, that's really significant!
@johnthebeloved has returned to some of these explorations recently. After extensive analysis, he concluded that caching is never beneficial for internal secondary instances on modern devices. In javarosa#445, he has turned off serialization of internal secondary instances and ensured that these are always read directly from XML, even when the form definition is loaded from the form cache. On a Galaxy Tab A, that means about a 6x reduction in load time for the Nigeria Wards form from ~45 seconds to ~7 seconds.
We've discussed various hypotheses about why serializing and deserializing the contents of internal secondary instances is significantly slower than reading them from XML. The major theme is that modern Android devices seem to be much more IO-bound than CPU- or memory-bound. Secondary instances tend to have very simple structures because they're generally used as itemsets in selects or to look up individual values. Serializing them requires writing out a lot of redundant information in each TreeElement and that IO is very expensive (as @dcbriccetti found when switching from computer to device). Reading from XML is a lot less IO intensive. This is a good reminder that code put in just to improve performance should be reviewed periodically as device characteristics evolve because something that used to help could suddenly start slowing down the common case.
All this to say that as of JavaRosa v2.15 / Collect v1.23, the form processing metrics table above should look quite different for forms with large non-main instances because cache write and cache read times will be much lower. Thanks, @dcbriccetti for all the groundwork and @johnthebeloved for the latest improvements!
