What could be simpler than a file copy? Well, it turned out that I underestimated such an easy task.
Here is the scenario. During the very first NativeScript for Android application startup the runtime extracts all JavaScript asset files to the internal device storage. The source code is quite simple and it was based on this example.
static final int BUFSIZE = 100000;
private static void copyStreams(InputStream is, FileOutputStream fos) {
BufferedOutputStream os = null;
try {
byte data[] = new byte[BUFSIZE];
int count;
os = new BufferedOutputStream(fos, BUFSIZE);
while ((count = is.read(data, 0, BUFSIZE)) != -1) {
os.write(data, 0, count);
}
os.flush();
} catch (IOException e) {
Log.e(LOGTAG, "Exception while copying: " + e);
} finally {
try {
if (os != null) {
os.close();
}
} catch (IOException e2) {
Log.e(LOGTAG, "Exception while closing the stream: " + e2);
}
}
}
It is important to note the in our code BUFSIZE constant has value 100000 while in the original example the value is 5192. While this code works as expected it turns out it is quite slow.
In our scenario we extract around 200 files and on LG Nexus 5 device it takes around 5.75 seconds. This is a lot of time. It turned out that most of this time is spent inside the garbage collector.
D/dalvikvm(8611): GC_FOR_ALLOC freed 265K, 2% free 17131K/17436K, paused 8ms, total 8ms D/dalvikvm(8611): GC_FOR_ALLOC freed 398K, 4% free 16930K/17636K, paused 11ms, total 11ms D/dalvikvm(8611): GC_FOR_ALLOC freed 197K, 4% free 16930K/17636K, paused 7ms, total 7ms ... around 650 more lines
The first thing I optimized was to make data variable a class member.
static final int BUFSIZE = 100000;
static final byte data[] = new byte[BUFSIZE];
private static void copyStreams(InputStream is, FileOutputStream fos) {
// remove 'data' local variable
}
I thought this will solve the GC problem but when I ran the application I was greeted with the following familiar log messages.
D/dalvikvm(8408): GC_FOR_ALLOC freed 248K, 2% free 17212K/17496K, paused 7ms, total 8ms D/dalvikvm(8408): GC_FOR_ALLOC freed 417K, 4% free 17029K/17696K, paused 8ms, total 8ms D/dalvikvm(8408): GC_FOR_ALLOC freed 199K, 4% free 17029K/17696K, paused 7ms, total 7ms ... around 330 more lines
This time it took around 2.25 seconds to extract the files. And the GC kicked 330 times instead of 660 times. Well, it was better but it wasn’t what I wanted. The GC kicked twice less than the previous example but still it was too much.
The next thing I tried is to set BUFSIZE to 4096 instead of 100000.
static final int BUFSIZE = 4096;
This time it took around 0.85 seconds to extract the assets and the GC kicked 8 times.
D/dalvikvm(8218): GC_FOR_ALLOC freed 323K, 3% free 17137K/17496K, paused 8ms, total 8ms D/dalvikvm(8218): GC_FOR_ALLOC freed 673K, 5% free 16947K/17684K, paused 8ms, total 9ms D/dalvikvm(8218): GC_FOR_ALLOC freed 512K, 5% free 16947K/17684K, paused 8ms, total 9ms ... just 5 more lines
It was a nice improvement but I thought it should be faster than this. I was still puzzled with this relatively high level of GC activity so I decided to read the online documentation.
A specialized
OutputStreamfor class for writing content to an (internal) byte array. As bytes are written to this stream, the byte array may be expanded to hold more bytes.
I’ve should read this before I start. It was a good lesson to me.
Once I knew what happens inside BufferedOutputStream internals I decided just not to use it. I call write method of FileOutputStream and voilà. The time to extract the assets is around 0.65 seconds and the GC kicks 4 times at most.
Out of curiosity I decided to try to bypass the GC using libzip C library. It took less than 0.2 seconds to extract the assets. Another option is to use AAssetManager class from NDK but I haven’t tried it yet. Anyway, it seems that IO processing is one of those areas where unmanaged code outperforms Java.