Android 4.4 のARTのブートログを見てみた

前回の記事(Android 4.4に入ったARTのソースを見た感想 - 組み込みの人。)ではソースコードを見ただけで、動かしてはいませんでした。
今回はAndroid 4.4のソースコードを自分でビルドしてemulatorを作り、そのブートログを見て気がついたことを書きます。

採取したブートログはここからたどれます。
KMC Staff Blog:各種Android端末のブートログ

ARTに切り替えてからの初回起動と2回目起動の違い

まずはデフォルトであるDalvikで今まで通り5種類のログをとりました。(カーネルログ、Androidのlogcat、Androidのprop、/proc/cpuinfo、/proc/config.gz)
その後、SettingアプリのDeveloper optionのところで、runtimeをARTに切り替えました。ダイアログに従って進むと再起動がかかります。(しかし、実際には終了処理がなぜかいつまでたっても終わらなかったので、emulatorを強制終了させました。)
これでもう一度emulatorを起動すればruntimeにARTを選択した状態で起動するはずです。ARTに切り替えた最初の起動では特別な処理が行われると思うので、貴重です。ログが欠けたりしないように、以下のようにしてlogcatの結果が逐次ファイルに保存されるようにしました。

 $ emulator &
 $ adb logcat |tee logcat_1st.txt

そのlogcat_1st.txtはここに置きました。

予想通り、ARTに切り替えたあとの最初の起動ではシステムのdexファイルをコンパイルするので時間がかかりました。ログを見ると以下のコマンドが実行されていました。(長いので横スクロールさせてみてください。)

I/art     (   56): GenerateImage: /system/bin/dex2oat --image=/data/dalvik-cache/system@framework@boot.art@classes.dex --runtime-arg -Xms64m --runtime-arg -Xmx64m --dex-file=/system/framework/core-libart.jar --dex-file=/system/framework/conscrypt.jar --dex-file=/system/framework/okhttp.jar --dex-file=/system/framework/core-junit.jar --dex-file=/system/framework/bouncycastle.jar --dex-file=/system/framework/ext.jar --dex-file=/system/framework/framework.jar --dex-file=/system/framework/framework2.jar --dex-file=/system/framework/telephony-common.jar --dex-file=/system/framework/voip-common.jar --dex-file=/system/framework/mms-common.jar --dex-file=/system/framework/android.policy.jar --dex-file=/system/framework/services.jar --dex-file=/system/framework/apache-xml.jar --dex-file=/system/framework/webviewchromium.jar --oat-file=/data/dalvik-cache/system@framework@boot.art@classes.oat --base=0x60000000 --image-classes-zip=/system/framework/framework.jar --image-classes=preloaded-classes
I/dex2oat (  119): dex2oat: /data/dalvik-cache/system@framework@boot.art@classes.oat

システムのjarファイルをまとめてコンパイルしてひとつのoatファイル (/data/dalvik-cache/system@framework@boot.art@classes.oat)を生成しています。

それが終わると全てのAndroidアプリのプロセスの元となるZygoteが起動し、そこからforkして各アプリのプロセスが開始されます。それぞれのアプリが必要となるdexファイルをロードしようとしますが、そのときにdex2oatコマンドによってoatファイルにコンパイルされます。以下のようなパターンのログが多数出ています。

W/art     (  370): Failed to find ELF magic in /system/framework/com.android.location.provider.odex: dey
W/art     (  370): Failed to find ELF magic in /data/dalvik-cache/system@framework@com.android.location.provider.jar@classes.dex: dey
I/art     (  370): DexFile_isDexOptNeeded cache file /data/dalvik-cache/system@framework@com.android.location.provider.jar@classes.dex does not exist for /system/framework/com.android.location.provider.jar
I/dex2oat (  397): dex2oat: /data/dalvik-cache/system@framework@com.android.location.provider.jar@classes.dex

これが多数くりかえされているので、起動に時間がかかっています。ずっとブートアニメーションのままなので、logcatの情報を見ていなければ、固まったと思うほどです。最後には見慣れたアイコンの画面が表示されて起動が完了しました。

一度emulatorを終了させて、もう2回目の起動のログを採取します。

 $ emulator &
 $ adb logcat |tee logcat.txt

今度はそれほど時間がかからずに起動しました。
logcat.txtはここに置きました。
/data/dalvik-cacheに生成したoatファイルが使用されているようで、dex2oatコマンドのログは出てきません。
今まで使っていなかったアプリを起動すると、そのときにdex2oatコマンドによるコンパイルが行われることがlogcatのログで観測できます。

ARTでのアプリのプロセスのメモリマップ

oatファイルはELFの共有ライブラリの一種だろうと予想しているのですが、それを確認するためにアプリのプロセスのメモリマップを見てみます。
まずはpsコマンドでプロセスIDを調べます。psコマンドの結果

...
root 55 1 231428 40376 ffffffff b6ea5568 S zygote
...
u0_a8 545 55 244384 35580 ffffffff b6ea65cc S com.android.launcher

zygoteは55, launcherは545とわかったので、それぞれのメモリマップを取得します。

$ adb shell cat /proc/55/maps > maps_zygote.txt
$ adb shell cat /proc/545/maps > maps_Launcher2.txt

maps_zygote.txt
maps_Launcher2.txt

maps_zygote.txt を見ると、/data/dalvik-cache/system@framework@boot.art@classes.oat は以下のようにメモリにマッピングされています。(長いので横スクロールさせてみてください。)

60a94000-62343000 r--p 00000000 1f:01 150        /data/dalvik-cache/system@framework@boot.art@classes.oat
62343000-6458f000 r-xp 018af000 1f:01 150        /data/dalvik-cache/system@framework@boot.art@classes.oat
6458f000-64590000 rw-p 03afb000 1f:01 150        /data/dalvik-cache/system@framework@boot.art@classes.oat

2番目の行はreadとexecuteの許可がついています。つまりこのファイルはただのデータでなくて、実行命令を含むものとして扱われています。
maps_Launcher2.txtではそれに追加して、/data/dalvik-cache/system@priv-app@Launcher2.apk@classes.dexが以下のようにマッピングされています。(長いので横スクロールさせてみてください。)

afc3e000-afccd000 r--p 00000000 1f:01 101        /data/dalvik-cache/system@priv-app@Launcher2.apk@classes.dex
afccd000-afda5000 r-xp 0008f000 1f:01 101        /data/dalvik-cache/system@priv-app@Launcher2.apk@classes.dex
afda5000-afda6000 rw-p 00167000 1f:01 101        /data/dalvik-cache/system@priv-app@Launcher2.apk@classes.dex
afda6000-afe07000 r--s 00e4f000 1f:00 1116       /system/priv-app/Launcher2.apk
afe07000-afe0e000 r--s 00eb4000 1f:00 1116       /system/priv-app/Launcher2.apk

これはサフィックスが.dexですが、おそらく中身はoatですね。データだけでなくて、実行命令を含んでいます。

コンパイル結果のoatファイルを取り出してみる

この2つのファイルを取り出してみます。

$ adb pull /data/dalvik-cache/system@framework@boot.art@classes.oat
$ adb pull /data/dalvik-cache/system@priv-app@Launcher2.apk@classes.dex

fileコマンドで調べると

$ file system@*
system@framework@boot.art@classes.oat:     ELF 32-bit LSB shared object, ARM, version 1 (GNU/Linux), dynamically linked, stripped
system@priv-app@Launcher2.apk@classes.dex: ELF 32-bit LSB shared object, ARM, version 1 (GNU/Linux), dynamically linked, stripped

やはりARMの実行バイナリを含むELFのshared objectでした。
(x86Androidならば、もちろんx86の実行バイナリを含むELFのshared objectになるはずです。)

$ arm-linux-androideabi-objdump -h system@priv-app@Launcher2.apk@classes.dex 

system@priv-app@Launcher2.apk@classes.dex:     file format elf32-littlearm

Sections:
Idx Name          Size      VMA       LMA       File off  Algn
  0 .dynsym       00000040  000000d4  000000d4  000000d4  2**2
                  CONTENTS, ALLOC, LOAD, READONLY, DATA
  1 .dynstr       00000047  00000114  00000114  00000114  2**0
                  CONTENTS, ALLOC, LOAD, READONLY, DATA
  2 .hash         0000001c  0000015c  0000015c  0000015c  2**2
                  CONTENTS, ALLOC, LOAD, READONLY, DATA
  3 .rodata       0008e000  00001000  00001000  00001000  2**12
                  CONTENTS, ALLOC, LOAD, READONLY, DATA
  4 .text         000d7af2  0008f000  0008f000  0008f000  2**12
                  CONTENTS, ALLOC, LOAD, READONLY, CODE
  5 .dynamic      00000038  00167000  00167000  00167000  2**12
                  CONTENTS, ALLOC, LOAD, DATA

このファイルをarm-linux-androideabi-objdump -d としても逆アセンブルはできませんでしたが、oatdumpコマンドを使うと中身を見ることができます。

まとめ

前回の記事(Android 4.4に入ったARTのソースを見た感想 - 組み込みの人。)では、ソースコードだけを見て書きましたが、実際に動かしてみることで以下のことが確認できました。

  • ARTはAOTコンパイルを行うということ
  • AOTコンパイルはdex2oatコマンドで行われること
  • AOTコンパイルは初回のdexファイル使用時に行われて、次回以降はコンパイル済みのoatファイルが使用されること
  • oatファイルはELFの共有ライブラリの一種であること

コンパイルされたoatファイルをoatdumpコマンドで見ると、いろいろ興味深いことがありましたが、それは別の記事に書きます。
続きを書きました。Android 4.4 のARTのコンパイルしたコードを見た感想 - 組み込みの人。