2010年07月13日
KZM-CA9-01ボードのandroid用カーネルを2.6.32にアップデートしてみた(その1)
KZM-CA9-01ボード(Cortex-A9 Quad core)のandroid用カーネルには2.6.29ベースのものを使っていましたが、これを2.6.32にアップデートしました。その作業の様子を紹介します。
準備
まずは現在動かしているカーネルのソースからこのボードに固有の変更を抽出します。
Androidのソースリポジトリのkernel/common.gitのandroid-2.6.29のブランチの2009年7月の時点のものがベースになっています。そこからdiffコマンドでパッチを生成しました。
そのパッチをandroid-2.6.29のブランチの先頭にあててみて動作を確認しました。とりあえずこれでandroid-2.6.29ブランチの最新にアップデートすることができました。
一日目 ...やみくもにやって失敗!
今度はandroid-2.6.32のブランチのソースをcheckoutし、そこにえいや!とさきほどのパッチを一気にあててみました。
たくさんrejectされましたが、気合で修正して、気合でコンパイルが通るところまで持ち込みました。
しかしこの作業をしながら気がついたのですが、2.6.29の段階ではまだまだSMP対応やarmv7対応が枯れていなかったらしく、このボード固有の変更以外にもたくさん変更されています。特にSMP対応は同じところを少し違う変更になっているところもあり、このパッチをあてることで一貫性が保たれるか疑問でした。
なんとかvmlinuxがビルドできたものの、やはり全く動きません。たぶんこの方法ではダメです。頭を冷やして作戦の練り直し。
二日目 ...お?生命反応あり。
まずパッチの内容を以下の3種類に分類しました。
- ボード固有の変更
- SMPに関する変更
- ARMに固有の変更
SMPに関する変更とARMに固有の変更は2.6.32ではすでにマージされていると仮定して、ボード固有の変更だけを適用するようにしました。
また、ボード固有の追加ファイル(ディレクトリ arch/arm/mach-a9tc以下にあるもの)も2.6.29から2.6.32への変更の影響を受けるので修正が必要です。これはボードの構成が似ているrealviewを参考にして
- 2.6.29でのmach-a9tcとmach-realviewとの間の違い
- mach-realviewの2.6.29から2.6.32との間の違い
の2つをにらみながら修正していきました。
そしてコンパイルが通ったらさっそくvmlinuxを実機にロードして試してみました。
すると ... シリアルコンソールにログが出て、DHCPサーバにIPアドレスを要求するところで止まりました。
「こいつ、動くぞ!?」
しかしもう一度リセットから動かすと今度はシリアルコンソールに全く何も出ません。
繰り返すと症状にばらつきがあります。PARTNER-Jetをつないでいるので、シリアルコンソールに何もでなくてもどこでループしているのかがわかります。
PARTNER-Jetでブレークしたところからステップして様子を見ていると普通のforループをぐるぐるしているようです。
「なんでこのループを抜けてこないの?」
Cのソース上でステップしてもわからないのでCソースと逆アセンブルを両方表示するようにモードを切り替えて追っていくと、なんとコードの途中で16バイト連続で0になっているところがありました。コンパイラがこんなコードを生成するはずはなく、明らかにメモリが破壊されています。(...今思えば、このときのスクリーンショットを保存しておけばよかった...)
「この症状はやっぱりキャッシュの設定を間違えたかな?」
arch/arm/mm/proc-v7.Sとarch/arm/mm/cache-v7.Sを集中的の調べて、動作している2.6.29カーネルと同じ方法でキャッシュの初期化が行われるように手直ししました。
修正したvmlinuxを起動してみると ...
「あ、起動した!」
NFSでルートファイルシステムのマウントに成功し、LCDの画面には"A n d r o i d"と表示されてカーソルが点滅しています。
しかしいつまで待っても次のアニメーションに画面が変わりません。
シリアルコンソールにシェルのプロンプトが出ているので、そこでpsと打ち込んでみると、しばらくしてからプロセスの一覧が出ましたが、いつも見慣れているものよりも明らかにプロセスの数が少ない。
「どこでこけたのかな?」
シリアルコンソールでlogcatとうちこむとログがでてきたが、エラーの様子はない。遅いけど少しづつ進んでいます。
「まだ生きてる。でも異常に遅い??」
画面をみるとandroidがアニメーションしていました。ただしちらつきがはげしい。いったん止めてやりなおそうとしたときにちょうどアニメーションが終わってロック画面になりました。キーを押すとちらつきながらもホーム画面が表示されました。キーもタッチパネルも効いているようです。
リセットしてもういちどやり直しても同じように遅い。make menuconfigでSMPを有効にして再度ビルドして動かしてみました。
SMPでも動いている!! ただし体感的に20倍以上遅い。
「いままでの経験上、動作は正しいけど異常に遅いのはキャッシュが効いていないということ?」
「あるいは割り込みが異常な頻度で発生してるとか?」
terminalでは流れてしまっていたシリアルコンソールのログをさかのぼって見て見たら、調べるべき点がわかりました。
とりあえず、今日のところはここまで。(続く。)
長いですけどそのときのログをここに貼っておきます。
Board: A9TC board DRAM: 256 MB Flash: 64 MB In: serial Out: serial Err: serial Hit any key to stop autoboot: 3 Linux version 2.6.32.9 (koba@koba-linux) (gcc version 4.4.0 (GCC) ) #18 SMP Sat Jul 10 19:55:01 JST 2010 CPU: ARMv7 Processor [410fc091] revision 1 (ARMv7), cr=10c53c7f CPU: VIPT nonaliasing data cache, VIPT nonaliasing instruction cache Machine: A9TC Memory policy: ECC disabled, Data cache writealloc Truncating RAM at 60000000-7fffffff to -77ffffff (vmalloc region overlap). PERCPU: Embedded 6 pages/cpu @c06e2000 s3520 r8192 d12864 u65536 pcpu-alloc: s3520 r8192 d12864 u65536 alloc=16*4096 pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 Built 1 zonelists in Zone order, mobility grouping on. Total pages: 97536 Kernel command line: root=/dev/nfs nfsroot=192.168.1.26:/export/android/root ip=dhcp noinitrd init=/init console=ttyAMA0,115200 mem=512M rootwait rw PID hash table entries: 2048 (order: 1, 8192 bytes) Dentry cache hash table entries: 65536 (order: 6, 262144 bytes) Inode-cache hash table entries: 32768 (order: 5, 131072 bytes) Memory: 384MB = 384MB total Memory: 385408KB available (2896K code, 794K data, 104K init, 0K highmem) Hierarchical RCU implementation. NR_IRQS:96 Console: colour dummy device 80x30 Calibrating delay loop... 797.90 BogoMIPS (lpj=3989504) Mount-cache hash table entries: 512 CPU: Testing write buffer coherency: ok Calibrating local timer... 199.98MHz. CPU1: Booted secondary processor CPU2: Booted secondary processor CPU3: Booted secondary processor Brought up 4 CPUs SMP: Total of 4 processors activated (3191.60 BogoMIPS). NET: Registered protocol family 16 L2X0 cache controller enabled Serial: AMBA PL011 UART driver dev:f1: ttyAMA0 at MMIO 0x100e3000 (irq = 84) is a AMBA/PL011 console [ttyAMA0] enabled bio: create slabat 0 SCSI subsystem initialized usbcore: registered new interface driver usbfs usbcore: registered new interface driver hub usbcore: registered new device driver usb Switching to clocksource timer1 NET: Registered protocol family 2 IP route cache hash table entries: 4096 (order: 2, 16384 bytes) TCP established hash table entries: 16384 (order: 5, 131072 bytes) TCP bind hash table entries: 16384 (order: 5, 131072 bytes) TCP: Hash tables configured (established 16384 bind 16384) TCP reno registered NET: Registered protocol family 1 RPC: Registered udp transport module. RPC: Registered tcp transport module. RPC: Registered tcp NFSv4.1 backchannel transport module. a9tc_nand_probe: 449246 2c da 80 95 50 ashmem: initialized msgmni has been set to 753 io scheduler noop registered io scheduler anticipatory registered (default) CLCD: a9tc hardware, 800x480 display Console: switching to colour frame buffer device 100x30 loop: module loaded smsc911x: Driver version 2008-10-21. irq 66: nobody cared (try booting with the "irqpoll" option) [ ] (unwind_backtrace+0x0/0xd8) from [ ] (__report_bad_irq+0x30/0x8c) [ ] (__report_bad_irq+0x30/0x8c) from [ ] (note_interrupt+0x148/0x1d0) [ ] (note_interrupt+0x148/0x1d0) from [ ] (handle_level_irq+0xe8/0x14c) [ ] (handle_level_irq+0xe8/0x14c) from [ ] (asm_do_IRQ+0x80/0xb8) [ ] (asm_do_IRQ+0x80/0xb8) from [ ] (__irq_svc+0x38/0xc0) Exception stack(0xd7841dc0 to 0xd7841e08) 1dc0: d7841e08 00000000 00000000 c034a6e0 d7840000 00000202 00000000 c03119fc 1de0: c0310040 0000000a c001c0a8 00000000 000000c7 d7841e08 c00443e8 c00442cc 1e00: 20000113 ffffffff [ ] (__irq_svc+0x38/0xc0) from [ ] (__do_softirq+0x50/0x128) [ ] (__do_softirq+0x50/0x128) from [ ] (irq_exit+0x44/0x90) [ ] (irq_exit+0x44/0x90) from [ ] (asm_do_IRQ+0x84/0xb8) [ ] (asm_do_IRQ+0x84/0xb8) from [ ] (__irq_svc+0x38/0xc0) Exception stack(0xd7841e58 to 0xd7841ea0) 1e40: c03119fc 60000013 1e60: 00000000 00000000 c03119c0 d7bdcee0 00000042 c03119fc c03119e0 d7bdf000 1e80: 60000013 d7bdf000 00000000 d7841ea0 c006c0b0 c0247324 60000013 ffffffff [ ] (__irq_svc+0x38/0xc0) from [ ] (_spin_unlock_irqrestore+0x28/0x2c) [ ] (_spin_unlock_irqrestore+0x28/0x2c) from [ ] (__setup_irq+0x248/0x31c) [ ] (__setup_irq+0x248/0x31c) from [ ] (request_threaded_irq+0xd0/0x118) [ ] (request_threaded_irq+0xd0/0x118) from [ ] (smsc911x_drv_probe+0x574/0x9f0) [ ] (smsc911x_drv_probe+0x574/0x9f0) from [ ] (platform_drv_probe+0x18/0x1c) [ ] (platform_drv_probe+0x18/0x1c) from [ ] (driver_probe_device+0xa0/0x14c) [ ] (driver_probe_device+0xa0/0x14c) from [ ] (__driver_attach+0x60/0x84) [ ] (__driver_attach+0x60/0x84) from [ ] (bus_for_each_dev+0x48/0x84) [ ] (bus_for_each_dev+0x48/0x84) from [ ] (bus_add_driver+0x9c/0x218) [ ] (bus_add_driver+0x9c/0x218) from [ ] (driver_register+0xa8/0x138) [ ] (driver_register+0xa8/0x138) from [ ] (do_one_initcall+0x5c/0x1b4) [ ] (do_one_initcall+0x5c/0x1b4) from [ ] (kernel_init+0x16c/0x1f8) [ ] (kernel_init+0x16c/0x1f8) from [ ] (kernel_thread_exit+0x0/0x8) handlers: [ ] (smsc911x_irqhandler+0x0/0x4a4) Disabling IRQ #66 smsc911x-mdio: probed eth0: attached PHY driver [Generic PHY] (mii_bus:phy_addr=0:01, irq=-1) smsc911x: Change mac address ff ff net eth0: MAC Address: 00:11:22:33:44:55 isp1760 isp1760.0: NXP ISP1760 USB Host Controller isp1760 isp1760.0: new USB bus registered, assigned bus number 1 isp1760 isp1760.0: bus width: 32, oc: digital isp1760 isp1760.0: irq 67, io mem 0x4e000000 isp1760 isp1760.0: USB ISP 1761 HW rev. 1 started usb usb1: configuration #1 chosen from 1 choice hub 1-0:1.0: USB hub found hub 1-0:1.0: 1 port detected ISP1760 USB device initialised Initializing USB Mass Storage driver... usbcore: registered new interface driver usb-storage USB Mass Storage support registered. input: a9tc_key as /devices/virtual/input/input0 input: a9tc_touch as /devices/virtual/input/input1 using rtc device, a9tc-rtc, for alarms a9tc-rtc a9tc-rtc: rtc core: registered a9tc-rtc as rtc0 usbcore: registered new interface driver usbhid usbhid: v2.6:USB HID core driver logger: created 64K log 'log_main' logger: created 256K log 'log_events' logger: created 64K log 'log_radio' logger: created 64K log 'log_system' TCP cubic registered NET: Registered protocol family 17 VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 0 a9tc-rtc a9tc-rtc: setting system clock to 1970-01-02 04:46:57 UTC (103617) port 1 high speed usb 1-1: new high speed USB device using isp1760 and address 2 port 1 high speed usb 1-1: configuration #1 chosen from 1 choice hub 1-1:1.0: USB hub found hub 1-1:1.0: 3 ports detected net eth0: SMSC911x/921x identified at 0xd8840000, IRQ: 66 Sending DHCP requests .., OK IP-Config: Got DHCP answer from 0.0.0.0, my address is 192.168.1.30 IP-Config: Complete: device=eth0, addr=192.168.1.30, mask=255.255.255.0, gw=192.168.1.62, host=192.168.1.30, domain=kmckk.jp, nis-domain=(none), bootserver=0.0.0.0, rootserver=192.168.1.26, rootpath= Looking up port of RPC 100003/2 on 192.168.1.26 Looking up port of RPC 100005/1 on 192.168.1.26 VFS: Mounted root (nfs filesystem) on device 0:12. Freeing init memory: 104K Warning: unable to open an initial console. ?init: cannot open '/initlogo.rle' ?init: cannot find '/system/etc/install-recovery.sh', disabling 'flash_recovery' sh: can't access tty; job control turned off # ps warning: `rild' uses 32-bit capabilities (legacy support in use) USER PID PPID VSIZE RSS WCHAN PC NAME root 1 0 224 208 c00a32e8 0000cdbc S /init root 2 0 0 0 c0052f70 00000000 S kthreadd root 3 2 0 0 c003b784 00000000 S migration/0 root 4 2 0 0 c00444f8 00000000 S ksoftirqd/0 root 5 2 0 0 c006abd4 00000000 S watchdog/0 root 6 2 0 0 c003b784 00000000 S migration/1 root 7 2 0 0 c00444f8 00000000 S ksoftirqd/1 root 8 2 0 0 c006abd4 00000000 S watchdog/1 root 9 2 0 0 c003b784 00000000 S migration/2 root 10 2 0 0 c00444f8 00000000 S ksoftirqd/2 root 11 2 0 0 c006abd4 00000000 S watchdog/2 root 12 2 0 0 c003b784 00000000 S migration/3 root 13 2 0 0 c00444f8 00000000 S ksoftirqd/3 root 14 2 0 0 c006abd4 00000000 S watchdog/3 root 15 2 0 0 c004f3d4 00000000 S events/0 root 16 2 0 0 c004f3d4 00000000 S events/1 root 17 2 0 0 c004f3d4 00000000 S events/2 root 18 2 0 0 c004f3d4 00000000 S events/3 root 19 2 0 0 c004f3d4 00000000 S khelper root 20 2 0 0 c0058f60 00000000 S async/mgr root 21 2 0 0 c004f3d4 00000000 S suspend root 22 2 0 0 c0080dac 00000000 S sync_supers root 23 2 0 0 c00815e4 00000000 S bdi-default root 24 2 0 0 c004f3d4 00000000 S kblockd/0 root 25 2 0 0 c004f3d4 00000000 S kblockd/1 root 26 2 0 0 c004f3d4 00000000 S kblockd/2 root 27 2 0 0 c004f3d4 00000000 S kblockd/3 root 28 2 0 0 c004f3d4 00000000 S ksuspend_usbd root 29 2 0 0 c019247c 00000000 S khubd root 30 2 0 0 c004f3d4 00000000 S kmmcd root 35 2 0 0 c004f3d4 00000000 S rpciod/0 root 36 2 0 0 c004f3d4 00000000 S rpciod/1 root 37 2 0 0 c004f3d4 00000000 S rpciod/2 root 38 2 0 0 c004f3d4 00000000 S rpciod/3 root 39 2 0 0 c006aeb8 00000000 S khungtaskd root 40 2 0 0 c007bbbc 00000000 S kswapd0 root 41 2 0 0 c004f3d4 00000000 S aio/0 root 42 2 0 0 c004f3d4 00000000 S aio/1 root 43 2 0 0 c004f3d4 00000000 S aio/2 root 44 2 0 0 c004f3d4 00000000 S aio/3 root 45 2 0 0 c004f3d4 00000000 S nfsiod root 46 2 0 0 c004f3d4 00000000 S usbhid_resumer root 47 2 0 0 c004f3d4 00000000 S binder root 52 1 632 308 c0041e68 afd0e80c S /system/bin/sh system 53 1 696 244 c01c56ec afd0db9c S /system/bin/servicemanager root 54 1 3632 524 ffffffff afd0e20c S /system/bin/vold root 55 1 3604 496 ffffffff afd0e20c S /system/bin/netd root 56 1 560 240 c01d476c afd0e52c S /system/bin/debuggerd radio 57 1 3236 640 ffffffff afd0e20c S /system/bin/rild root 58 1 2648 704 c009d5bc b000397c D /system/bin/app_process media 59 1 1940 644 c022ec30 b000397c D /system/bin/mediaserver bluetooth 60 1 1156 576 c00a32e8 afd0e9dc S /system/bin/dbus-daemon root 61 1 692 252 c01d476c afd0e52c S /system/bin/installd keystore 62 1 1512 388 c01d476c afd0e52c S /system/bin/keystore root 63 1 1244 140 ffffffff 0000f474 S /sbin/adbd root 64 2 0 0 c00b1f74 00000000 S flush-0:12 root 70 52 784 324 00000000 afd0d8fc R ps # # # logcat --------- beginning of /dev/log/main I/DEBUG ( 56): debuggerd: Jul 5 2010 17:04:14 I/Netd ( 55): Netd 1.0 starting --------- beginning of /dev/log/system I/Vold ( 54): Vold 2.1 (the revenge) firing up D/Vold ( 54): Volume sdcard state changing -1 (Initializing) -> 0 (No-Media) W/Vold ( 54): No UMS switch available D/AndroidRuntime( 58): D/AndroidRuntime( 58): >>>>>>>>>>>>>> AndroidRuntime START <<<<<<<<<<<<<< D/AndroidRuntime( 58): CheckJNI is ON D/dalvikvm( 58): creating instr width table I/ ( 59): ServiceManager: 0xacd0 W/AudioHardwareInterface( 59): Using stubbed audio hardware. No sound will be produced. D/AudioHardwareInterface( 59): setMode(NORMAL) I/CameraService( 59): CameraService started: pid=59 I/AudioFlinger( 59): AudioFlinger's thread 0xb390 ready to run D/AndroidRuntime( 58): --- registering native functions --- I/SamplingProfilerIntegration( 58): Profiler is disabled. I/Zygote ( 58): Preloading classes... D/dalvikvm( 58): GC_EXPLICIT freed 816 objects / 47208 bytes in 4ms D/dalvikvm( 58): GC_EXPLICIT freed 219 objects / 13560 bytes in 5ms D/dalvikvm( 58): GC_EXPLICIT freed 253 objects / 14336 bytes in 6ms D/dalvikvm( 58): GC_EXPLICIT freed 466 objects / 28872 bytes in 6ms D/dalvikvm( 58): GC_EXPLICIT freed 2090 objects / 108312 bytes in 205ms W/MediaProfiles( 58): could not find media config xml file D/dalvikvm( 58): GC_EXPLICIT freed 279 objects / 15968 bytes in 8ms D/dalvikvm( 58): GC_FOR_MALLOC freed 5088 objects / 225400 bytes in 17ms D/dalvikvm( 58): GC_FOR_MALLOC freed 11262 objects / 383224 bytes in 21ms D/dalvikvm( 58): GC_FOR_MALLOC freed 9866 objects / 463664 bytes in 23ms D/dalvikvm( 58): GC_FOR_MALLOC freed 8632 objects / 420968 bytes in 25ms D/dalvikvm( 58): GC_FOR_MALLOC freed 7814 objects / 463904 bytes in 25ms D/dalvikvm( 58): GC_FOR_MALLOC freed 7254 objects / 461624 bytes in 26ms D/dalvikvm( 58): GC_FOR_MALLOC freed 7560 objects / 462184 bytes in 26ms D/dalvikvm( 58): GC_FOR_MALLOC freed 7567 objects / 456840 bytes in 27ms D/dalvikvm( 58): GC_EXPLICIT freed 1176 objects / 76944 bytes in 24ms D/dalvikvm( 58): GC_EXPLICIT freed 596 objects / 29064 bytes in 24ms D/dalvikvm( 58): GC_EXPLICIT freed 449 objects / 25152 bytes in 25ms D/dalvikvm( 58): GC_EXPLICIT freed 308 objects / 35112 bytes in 34ms D/dalvikvm( 58): GC_EXPLICIT freed 279 objects / 18960 bytes in 35ms D/dalvikvm( 58): GC_EXPLICIT freed 341 objects / 18440 bytes in 36ms D/dalvikvm( 58): GC_EXPLICIT freed 449 objects / 28336 bytes in 36ms D/dalvikvm( 58): GC_EXPLICIT freed 529 objects / 53152 bytes in 40ms D/dalvikvm( 58): GC_EXPLICIT freed 623 objects / 34008 bytes in 40ms D/dalvikvm( 58): GC_EXPLICIT freed 861 objects / 46944 bytes in 40ms D/dalvikvm( 58): GC_EXPLICIT freed 1747 objects / 85560 bytes in 42ms D/dalvikvm( 58): GC_EXPLICIT freed 447 objects / 29384 bytes in 41ms D/dalvikvm( 58): GC_EXPLICIT freed 315 objects / 20120 bytes in 42ms I/Zygote ( 58): ...preloaded 1265 classes in 123830ms. D/dalvikvm( 58): GC_EXPLICIT freed 99 objects / 13952 bytes in 42ms
追加情報。
# vmstat procs memory system cpu r b free mapped anon slab in cs flt us ni sy id wa ir 0 1 375676 1316 1108 2504 0 88 2 0 0 2 99 99 0 0 2 375428 1360 1160 2528 26 85 1 0 0 2 99 99 0 0 1 375428 1368 1168 2524 8 70 0 0 0 1 99 99 0 0 3 375296 1408 1192 2532 8 78 4 0 0 2 99 99 0 0 1 375040 1416 1192 2532 8 59 1 0 0 1 0 99 0 0 0 375040 1468 1216 2532 8 78 0 2 0 2 99 49 0 0 0 374916 1468 1216 2532 8 72 0 0 0 1 99 20 0 0 2 374916 1548 1236 2520 8 78 2 1 0 2 99 99 0 0 2 374792 1560 1240 2520 8 56 1 1 0 1 99 99 0 0 2 374668 1584 1248 2508 8 72 2 0 0 1 99 99 0 0 0 374668 1712 1252 2512 8 59 0 0 0 0 99 38 0
さて、これであなたの次の一手は?