boot speed -- scan package, IO buffering, and prefetch

[Tomei]

Hello,

It seems package scanning speed is greatly influenced by IO buffering:

I did some simple experiment. I am testing with a fresh build so there
are NO apps under /data/app.

First boot up the phone. Then do either (A) or (B):

(A):

# stop
# sync; echo 3 > /proc/sys/vm/drop_caches
# start

(B):

# stop
# sync; echo 3 > /proc/sys/vm/drop_caches
# cat /system/app/*.apk > /dev/null
# start

case (A): I/PackageManager( 3114): Time to scan packages: 12.668
seconds
case (B): I/PackageManager( 3189): Time to scan packages: 7.032
seconds

Can PackageManagerService be easily reworked so that it pre-fetches
the buffers for the "next app to scan" in a separate thread?

I can't just blindly run a "cat /system/app/*.apk > /dev/null" before
package scanning happens, because doing so would cost more time than
the saving indicated from above ....

Thanks!

[David Turner]

The problem is that you didn't count the time to do the "cat" in your overall benchmark.

Hence, the savings you present are purely hyptohetical, even if you implement prefetching.

--
unsubscribe: android-porti...@googlegroups.com
website: http://groups.google.com/group/android-porting

[Tim Bird]

This sounds interesting. So based on David's response, what is
'time cat /system/app/*.apk >/dev/null' ??

> I can't just blindly run a "cat /system/app/*.apk > /dev/null" before
> package scanning happens, because doing so would cost more time than
> the saving indicated from above ....

I'm currently looking at the package scan time as well.

I instrumented PackageManagerService to log each package (so I
could get the delta per package) A list of the top durations,
sorted by duration, is shown below:

delta log time
...
0.609 [ 29.573 ] I/PackageManager( 769): Parsing package in file: /system/framework/framework-res.apk
0.954 [ 34.127 ] I/PackageManager( 769): Parsing package in file: /system/app/Camera.apk
1.117 [ 42.870 ] I/PackageManager( 769): Parsing package in file: /data/app/ApiDemos.apk
1.148 [ 30.370 ] I/PackageManager( 769): Parsing package in file: /system/app/Music.apk
1.227 [ 37.971 ] I/PackageManager( 769): Parsing package in file: /system/app/Launcher.apk
1.453 [ 32.229 ] I/PackageManager( 769): Parsing package in file: /system/app/Gallery.apk
1.742 [ 36.104 ] I/PackageManager( 769): Parsing package in file: /system/app/Settings.apk
2.297 [ 39.370 ] I/PackageManager( 769): Parsing package in file: /system/app/Contacts.apk

I noticed that the delta time, or elapsed time to load the
package, is strongly related to the package size. I've been
trying to read through the code to find out where the time
is being spent. I've only seen parsing of AndroidManifest.xml
so far, but since these always occur at the front of .apks,
I wouldn't think this would account for a scan duration
relating to the whole package size. Are there other resources
being loaded during the package scan? Is the whole file
read and processed - not just the manifest? From strace, it's
clear that the accesses are via an mmapped file (there are no
read syscalls in the strace), so I haven't gotten a clear
picture of the read pattern of the files.

There are a lot of layers of code here, (and the method tracer
is broken on my platform) so it's taking me a bit of time (ha, ha)
to figure out where the time is actually being spent.

Any pointers or additional information would be appreciated.

Thanks,
-- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Network Entertainment
=============================