Android开机log和常见异常的分析

Android开机log分析

分析开机log，一是可以理一下android启动流程，二是可以通过log定位错误，下面列举一些常见android程序发生错误时抛出的异常，查找关键字xxxException可以快速定位android层错误以及原因：

Java.lang.NullPointerException：
空指针异常
java.lang.ClassNotFoundException：
找不到类抛出的异常
java.lang.ArithmeticException：
一个整数“除以零”时抛出的异常
java.lang.ArrayIndexOutOfBoundsException:
数组越界访问以后抛出的异常
java.lang.IllegalArgumentException：
传入非法参数抛出的异常
java.lang.IllegalAccessException：
当应用程序要调用一个类，但当前的方法即没有对该类的访问权限便会出现这个异常
java.lang.SecturityException：
安全异常。由安全管理器抛出，用于指示违反安全情况的异常
java.lang.RuntimeException
运行时异常。是所有Java虚拟机正常操作期间可以被抛出的异常的父类。
 java.lang.NumberFormatException：
字符串转换为数字异常：
java.lang.StackOverflowError：
堆栈溢出错误。当一个应用递归调用的层次太深而导致堆栈溢出时抛出该错误。
java.lang.RuntimeException 
java.lang.OutOfMemoryError：
内存不足错误。当可用内存不足以让Java虚拟机分配给一个对象时抛出该错误。
java.lang.IOException：
输入输出异常
java.lang.AbstractMethodError：
抽象方法错误。当应用试图调用抽象方法时抛出。
java.lang.ClassFormatError：
类格式错误。当Java虚拟机试图从一个文件中读取Java类，而检测到该文件的内容不符合类的有效格式时抛出。
java.lang.InstantiationError：
实例化错误。当一个应用试图通过Java的new操作符构造一个抽象类或者接口时抛出该异常.
java.lang.InternalError：内部错误。用于指示Java虚拟机发生了内部错误。
java.lang.NoSuchMethodError
方法不存在错误。当应用试图调用某类的某个方法，而该类的定义中没有该方法的定义时抛出该错误。
java.lang.VirtualMachineError
虚拟机错误。用于指示虚拟机被破坏或者继续执行操作所需的资源不足的情况
java.lang.ClassCastException
类造型异常。假设有类A和B（A不是B的父类或子类），O是A的实例，那么当强制将O构造为类B的实例时抛出该异常。该异常经常被称为强制类型转换异常。
java.lang.InterruptedException
被中止异常。当某个线程处于长时间的等待、休眠或其他暂停状态，而此时其他的线程通过Thread的interrupt方法终止该线程时抛出该异常。
java.lang.IllegalStateException
违法的状态异常。当在Java环境和应用尚未处于某个方法的合法调用状态，而调用了该方法时，抛出该异常。
java.lang.ExceptionInInitializerError
初始化程序错误。当执行一个类的静态初始化程序的过程中，发生了异常时抛出。静态初始化程序是指直接包含于类中的static语句段。

开机关键log分析

1. android启动第一阶段：启动android第一个进程init，通过解析init.rc脚本，生成文件系统，启动vold、media、SurfaceFlinger等Nativie服务。在这个阶段你可以看到带“Android”文字静态logo和带“android”文字的开机动画
 [    3.947876] init: /dev/hw_random not found
========正常打印，找不到/dev/hw这个目录
 [    3.952580] init: cannot open '/initlogo.rle'
==========正常打印，第二个开机画面的内容是由文件/initlogo.rle来指定的。
如果文件/initlogo.rle不存在，或者在显示它的过程中出现异常，那么函数load_565rle_image的返回值就会等于-1，这时候函数console_init_action就以文本的方式来显示第二个开机画面，即向编号为0的控制台（/dev/tty0）输出带“ANDROID” 文字静态logo
[    4.019576] init: 
[    4.019583]  failed to mount pstore pstore /sys/fs/pstore   ret=-1 errnostr=No such file or directory 
 [    4.049219] EXT4-fs (actc): mounted filesystem with ordered data mode. Opts: noauto_da_alloc
[    4.070701] EXT4-fs (acte): mounted filesystem with ordered data mode. Opts: nodelalloc
================正常打印，挂载文件系统，一些挂载出错，主要是原因是文件不存在
 [    6.397025] init: value=512misc info read type=0, size=32
 [    6.417399] init: failed to open /data/system/entropy.dat
========正常打印，打开/data/system/entropy.dat时出错，
 [    6.435154] healthd: wakealarm_init: timerfd_create failed
========正常打印，healthd进程创建timerfd_create时失败
 [    6.453868] binder: 1140:1140 transaction failed 29189, size 0-0
[    6.497618] init: property 'sys.powerctl' doesn't exist while expanding '${sys.powerctl}'
[    6.506132] init: powerctl: cannot expand '${sys.powerctl}'
========解析属性值时出错，正常打印
12-31 16:00:06.510 I/installd( 1342): installd firing up
========启动守护进程installd服务：apk安装的服务
01-07 06:21:37.160 I/Vold    ( 1326): Vold 2.1 (the revenge) firing up
01-07 06:21:37.170 D/Vold    ( 1326): Volume sdcard state changing -1 (Initializing) -> 0 (No-Media)
========启动volume服务：主要是用来管理usb/sd卡等外部存储设备。平台可以对外部存储设备进行操作和轮询状态，当外部存储设备状态发生变化时，volume 服务也会实时报告平台。
01-07 06:21:37.500 I/SurfaceFlinger( 1333): SurfaceFlinger is starting
01-07 06:21:37.500 I/SurfaceFlinger( 1333): SurfaceFlinger's main thread ready to run. Initializing graphics H/W...
=======启动SurfaceFlinger服务：合成图像并显示到屏幕。启动该服务过程中会触发init启动一个bootanimation进程，其会开始启动动画显示，也就是我们看到的带“android”字样的启动动画
EGL_CONTEXT_PRIORITY_LEVEL_IMG ~~ used default 
01-07 06:21:38.460 D/Smart_Backlight( 1333): BackLight_Open!bl_maxval:780
01-07 06:21:38.460 D/Sub_Backlight( 1333): SubBackLight_Open!bl_level:1024,bl_stdval:0,data_format:2,bl_scene:0,width:800,height:480
01-07 06:21:38.460 D/Sub_Backlight( 1333): Get_Property:100
01-07 06:21:38.460 D/Sub_Backlight( 1333): SubBackLight_Open!adjust_strength:100!
01-07 06:21:38.460 D/Sub_Backlight( 1333): Get_Property:374
01-07 06:21:38.460 D/Sub_Backlight( 1333): SubBackLight_Open!start_minval:374!
01-02 01:01:29.640 E/BootAnimation( 1299): BootAnimation::music:boot
======= bootanimation进程启动，如前所述，会启动带“android”字样的动画，直到luncher界面以后会停止动画
01-07 06:21:39.350 I/mediaserver( 1341): ServiceManager: 0xb7460418
========启动mediaserver服务：音视频多媒体服务，通过binder的进程间通信方式来完成其他进程（如音乐播放器）的请求。
01-07 06:21:39.350 I/AudioFlinger( 1341): Using default 3000 mSec as standby time.
=======启动AudioFlinger服务：由mediaserver服务启动，是Android音频系统的两大服务之一，AudioFlinger向下访问AudioHardware，实现输出音频数据，控制音频参数。同时，AudioFlinger向上通过IAudioFinger接口提供服务
01-07 06:21:39.370 I/CameraService( 1341): CameraService started (pid=1341)
01-07 06:21:39.440 D/CameraService( 1341): CameraService::init
01-07 06:21:39.440 I/CameraService( 1341): Loaded "Actions CameraHal Module" camera module
=======系统初始化时会开启一个CameraService的守护进程，为上层应用提供camera对应的功能接口。并与与硬件抽象层之间通过回调函数传递数据。
01-07 06:21:39.470 I/AudioPolicyManagerBase( 1341): loadAudioPolicyConfig() loaded /system/etc/audio_policy.conf
01-07 06:21:39.800 I/AudioHardware( 1341): open control drv
01-07 06:21:39.800 I/AudioFlinger( 1341): loadHwModule() Loaded primary 
-------
2.android启动第二阶段：Zygote进程启动：
1）.生成Dalvik虚拟机，运行java程序
2）.将需要的类与资源加载到内存中，新运行的程序可直接使用这些资源，不必重新加载，加快了运行速度
3）.生成SystemService进程，该进程用来生成运行Android平台需要的一些主要的java核心服务
4）.生成新的android应用程序
01-07 06:21:44.240 I/Zygote  ( 1335): Preloading classes...
01-07 06:21:44.240 E/cutils-trace( 1335): Error opening trace file: No such file or directory (2)
01-07 06:21:44.240 D/dalvikvm( 1335): GC_EXPLICIT freed 40K, 8% free 522K/564K, paused 0ms+0ms, total 3ms
01-07 06:21:44.300 D/dalvikvm( 1335): GC_EXPLICIT freed 5K, 3% free 601K/616K, paused 0ms+1ms, total 7ms
01-07 06:21:44.330 D/dalvikvm( 1335): Note: class Landroid/app/ActivityManagerNative; has 179 unimplemented (abstract) methods
01-07 06:21:48.740 I/Zygote  ( 1335): ...preloaded 2777 classes in 4497ms.
========将需要的类到内存中
01-07 06:21:49.410 I/Zygote  ( 1335): Preloading resources...
01-07 06:21:49.440 W/Resources( 1335): Preloaded drawable resource #0x1080096 (android:drawable/toast_frame) that varies with configuration!!
01-07 06:21:49.440 W/Resources( 1335): Preloaded drawable resource #0x1080105 (android:drawable/btn_check_on_pressed_holo_light) that varies with configuration!!
01-07 06:21:49.440 W/Resources( 1335): Preloaded drawable resource #0x1080104 (android:drawable/btn_check_on_pressed_holo_dark) that varies with configuration!!
01-07 06:21:49.490 W/Resources( 1335): Preloaded drawable resource #0x1080102 (android:drawable/btn_check_on_holo_light) that varies with configuration!!
=========将需要的资源(xml文件、图像等)加载到内存中
01-07 06:21:57.490 I/SystemServer( 3146): Entered the Android system server!
=======启动SystemServer进程，该进程会启动电源管理器、Activity管理器、窗口管理器等java核心服务
01-07 06:21:57.940 D/Sensors ( 3146): AccelerationSensor::AccelerationSensor()
01-07 06:21:57.940 D/Sensors ( 3146): AccelerationSensor::~enable(0, 0)
01-07 06:21:58.000 I/Installer( 3146): connecting...
01-07 06:21:58.010 I/installd( 1342): new connection
01-07 06:21:58.010 I/SystemServer( 3146): Power Manager
========启动PowerManagerService：电源管理服务
01-07 06:21:58.010 I/SystemServer( 3146): Activity Manager
========启动ActivityManagerService：创建Activity管理器的服务
01-07 06:21:58.300 I/SystemServer( 3146): Display Manager
========启动DisplayManagerService：显示管理服务

01-07 06:21:58.340 I/SystemServer( 3146): Package Manager
01-07 06:21:58.400 V/PackageManager( 3146): BuiltinPkg file :/system/etc/builtinapk
01-07 06:21:58.450 I/PackageManager( 3146): Non-xml file /system/etc/permissions/extras in /system/etc/permissions directory, ignoring
01-07 06:21:58.490 D/SELinuxMMAC( 3146): Couldn't find install policy /data/security/mac_permissions.xml
01-07 06:21:58.500 D/SELinuxMMAC( 3146): Using install policy file /system/etc/security/mac_permissions.xml
========启动PackageManagerService：包管理器服务。遍历/system/priv-app、/system/app等目录下的apk的权限和安装信息等
01-07 06:22:03.660 I/SystemServer( 3146): User Service
01-07 06:22:03.660 I/SystemServer( 3146): Account Manager
===========启动UserManagerService：用户管理服务
01-07 06:22:03.680 I/SystemServer( 3146): Content Manager
01-07 06:22:03.680 I/SystemServer( 3146): System Content Providers
01-07 06:22:03.780 D/lights  ( 3146): #######open_lights  (backlight)######
01-07 06:22:03.780 D/lights  ( 3146): #######open_lights  (backlight) OK######
01-07 06:22:03.780 I/SystemServer( 3146): Lights Service
==========启动LightsService：光系统管理服务
01-07 06:22:03.780 I/SystemServer( 3146): Battery Service
========启动BatteryService：电池服务
01-07 06:22:03.790 I/SystemServer( 3146): Vibrator Service
========启动VibratorService：振动器系统管理服务
[   33.765371] request_suspend_state: wakeup (3->0) at 33747188755 (2011-01-07 14:22:03.817901502 UTC)
01-07 06:22:03.790 E/ConsumerIrService( 3146): Can't open consumer IR HW Module, error: -2
01-07 06:22:03.840 I/SystemServer( 3146): Alarm Manager
========启动AlarmManagerService:定时器服务
01-07 06:22:03.840 I/SystemServer( 3146): Init Watchdog
01-07 06:22:03.840 I/SystemServer( 3146): Input Manager
=========启动InputManagerService：输入子系统管理服务
01-07 06:22:03.840 I/InputManager( 3146): Initializing input manager, mUseDevInputEventForAudioJack=false
01-07 06:22:03.870 I/SystemServer( 3146): Window Manager
=========启动WindowManagerService：窗口管理服务
01-07 06:22:03.960 I/WindowManager( 3146): No existing display settings /data/system/display_settings.xml; starting empty
01-07 06:22:04.000 I/WindowManager( 3146): No keyguard interface!
01-07 06:22:04.010 D/BluetoothManagerService( 3146): Loading stored name and address
01-07 06:22:04.010 I/SystemServer( 3146): Bluetooth Manager Service
===========启动BluetoothManagerService：蓝牙服务
01-07 06:22:04.020 I/SystemServer( 3146): Input Method Service
01-07 06:22:04.030 D/EventHub( 3146): No input device configuration file found for device 'gslX680'.
01-07 06:22:04.300 I/SystemServer( 3146): Accessibility Manager
==========启动AccessibilityManager：
01-07 06:22:04.300 I/ActivityManager( 3146): Config changes=1df8 {1.0 ?mcc?mnc zh_CN ldltr sw480dp w800dp h480dp 160dpi lrg long 
01-07 06:22:04.330 I/SystemServer( 3146): Mount Service
==========启动MountService：管理sd挂载服务
01-07 06:22:04.490 I/SystemServer( 3146): LockSettingsService
==========启动LockSettingsService：管理锁屏的服务
01-07 06:22:04.490 I/SystemServer( 3146): Device Policy
01-07 06:22:04.490 I/SystemServer( 3146): Status Bar
01-07 06:22:04.490 I/SystemServer( 3146): Clipboard Service
01-07 06:22:04.490 I/SystemServer( 3146): NetworkManagement Service
========启动NetworkManagementService：网络管理服务
01-07 06:22:04.530 I/SystemServer( 3146): NetworkStats Service
=======启动NetworkStatsService：网络状态服务
01-07 06:22:04.530 W/MountService( 3146): getSecureContainerList() called when storage not mounted
01-07 06:22:04.560 I/SystemServer( 3146): NetworkPolicy Service
=======启动NetworkPolicyService：网络策略服务
01-07 06:22:04.600 I/SystemServer( 3146): Wi-Fi P2pService
=========启动WifiP2pService：管理P2P连接服务
01-07 06:22:04.600 W/PackageManager( 3146): Not granting permission android.permission.READ_LOGS to package com.actions.AL.Test (protectionLevel=50 flags=0x8be45)
01-07 06:22:05.420 I/SystemServer( 3146): Wi-Fi Service
=============启动WifiService：wifi管理服务
01-07 06:22:05.450 D/WifiHW  ( 3146): Unable to unload driver module "wlan_kk": No such file or directory
01-07 06:22:05.470 D/EthernetService( 3146): EthernetService construct starting
01-07 06:22:05.470 E/Netd    ( 1330): Failed to open /proc/sys/net/ipv6/conf/eth0/disable_ipv6: No such file or directory
01-02 01:01:57.130 F/SystemServer( 1627): java.lang.SecurityException: Unable to find app for caller android.app.ActivityThread$ApplicationThread@41924790 (pid=1627) when registering receiver android.app.LoadedApk$ReceiverDispatcher$InnerReceiver@41a2ed50
=======正常打印：导致SecurityException是因为发起此请求的应用所在的进程不是系统进程，并且此进程的包名列表中，并不包含要注册的receiver对应的package名称
01-07 06:22:05.470 I/SystemServer( 3146): Ethernet Service
=============启动EtherhetService：wifi管理服务
01-07 06:22:05.500 E/EthernetStateMachine( 3146): Failed to disable IPv6: java.lang.IllegalStateException: command '1 interface ipv6 eth0 disable' failed with '400 1 Failed to change IPv6 state (No such file or directory)'
======正常打印，未能使能IPv6
 01-07 06:22:05.500 D/ethernet( 3146): Unable to unload driver module "asix": No such file or directory
01-07 06:22:05.500 I/SystemServer( 3146): Connectivity Service
==========启动ConnectivityService：数据连接管理服务
01-07 06:22:05.500 D/ConnectivityService( 3146): ConnectivityService starting up
01-07 06:22:05.520 D/ethernet( 3146): Unable to unload driver module "sr9700": No such file or directory
01-07 06:22:05.520 D/ConnectivityService( 3146): wifiOnly=false
01-07 06:22:05.530 E/ConnectivityService( 3146): Ignoring protectedNetwork 
01-07 06:22:05.550 I/WifiService( 3146): WifiService starting up with Wi-Fi disabled
01-07 06:22:05.660 I/SystemServer( 3146): Network Service Discovery Service
01-07 06:22:05.660 D/NsdService( 3146): Network service discovery enabled true
01-07 06:22:05.660 I/SystemServer( 3146): UpdateLock Service
01-07 06:22:05.750 I/SystemServer( 3146): Notification Manager
========启动NotificationManager：通知管理器服务
01-07 06:22:05.760 I/SystemServer( 3146): Device Storage Monitor
========启动DeviceStorageMonitorService：设备存储监视服务
01-07 06:22:05.760 I/SystemServer( 3146): Location Manager
=======启动LocationManager：定位管理器服务
01-07 06:22:05.760 I/SystemServer( 3146): Country Detector
01-07 06:22:05.760 I/SystemServer( 3146): Search Service
=======启动SearchService：定位搜索器服务
01-07 06:22:05.770 I/SystemServer( 3146): DropBox Service
=======启动DropBoxService：剪切板服务服务
01-07 06:22:05.770 I/SystemServer( 3146): Wallpaper Service
========启动WallpaperService壁纸管理服务
01-07 06:22:05.780 I/SystemServer( 3146): Audio Service
========启动AudioService：音频管理服务

01-07 06:22:05.860 I/SystemServer( 3146): Wired Accessory Manager
01-07 06:22:05.860 I/SystemServer( 3146): USB Service
=======启动UsbService：usb管理服务
01-07 06:22:05.870 E/UsbDeviceManager( 3146): failed to write to /sys/class/android_usb/android0/f_rndis/ethaddr
01-07 06:22:05.880 I/SystemServer( 3146): Serial Service
=======启动SerialService：串口管理服务
01-07 06:22:05.880 I/SystemServer( 3146): Twilight Service
01-07 06:22:05.880 I/SystemServer( 3146): UI Mode Manager Service
01-07 06:22:05.890 I/SystemServer( 3146): Backup Service
========启动BackupService：备份管理服务
01-07 06:22:06.070 I/BackupManagerService( 3146): Scheduling backup for new app android
01-07 06:22:06.070 D/BackupManagerService( 3146): Now staging backup of android
01-07 06:22:06.190 I/BackupManagerService( 3146): Scheduling backup for new app com.android.providers.settings
01-07 06:22:06.190 D/BackupManagerService( 3146): Now staging backup of com.android.providers.settings
01-07 06:22:06.310 I/BackupManagerService( 3146):   com.google.android.googlequicksearchbox
01-07 06:22:06.310 I/SystemServer( 3146): AppWidget Service
========启动AppWidgetService：桌面管理服务
01-07 06:22:06.440 I/SystemServer( 3146): Print Service
========启动PrintService：打印管理服务
01-07 06:22:06.460 D/Atlas   ( 3146): Loaded configuration: SliceMinArea (768x768) flags=0x2 count=24
01-07 06:22:06.460 I/SystemServer( 3146): Media Router Service
01-07 06:22:06.470 I/WindowManager( 3146): SAFE MODE not enabled
01-07 06:22:06.670 I/Zygote  ( 3146): Process: zygote socket opened
01-07 06:22:06.690 V/KeyguardServiceDelegate( 3146): *** Keyguard started
01-07 06:22:06.690 V/KeyguardServiceDelegate( 3146): onSystemReady() called before keyguard service was ready
01-07 06:22:06.690 I/ActivityManager( 3146): Start proc com.android.systemui for service com.android.keyguard/.KeyguardService: pid=3198 uid=10012 
01-07 06:22:06.820 I/ActivityManager( 3146): System now ready
01-07 06:22:06.830 I/SystemServer( 3146): Making services ready
01-07 06:22:06.860 D/NetworkManagementService( 3146): enabling bandwidth control
01-07 06:22:06.860 D/DirectVolume( 1326): getDeviceNodes mDiskNumParts:0
01-07 06:22:06.860 D/DirectVolume( 1326): mDiskMinor:72
01-07 06:22:06.860 I/Vold    ( 1326): /dev/block/vold/93:72 being considered for volume sdcard
01-07 06:22:06.860 D/Vold    ( 1326): Volume sdcard state changing 1 (Idle-Unmounted) -> 3 (Checking)
01-07 06:22:06.870 D/MountService( 3146): volume state changed for /mnt/sdcard (unmounted -> checking)
01-07 06:22:07.100 V/KeyguardService( 3198): onCreate()
=======启动KeyguardService服务管理锁屏
01-07 06:22:07.120 I/fsck_msdos( 1326): ** Phase 2 - Check Cluster Chains
01-07 06:22:07.130 E/ActionOMXPlugin( 1341): In ActionOMXPlugin: libOMX_Core.so is openning!
01-07 06:22:07.130 E/ActionOMXPlugin( 1341): In ActionOMXPlugin: libAction_OMX_Core.so is openning!
01-07 06:22:07.260 D/SystemUIService( 3198): loading: class 
=========启动SystemUIService服务，管理StatusBar(状态栏)、NavigationBar(导航栏)
com.android.systemui.recent.Recents
01-07 06:22:07.270 D/SystemUIService( 3198): running: com.android.systemui.recent.Recents@418bf4c0
01-07 06:22:07.270 D/SystemUIService( 3198): loading: class com.android.systemui.statusbar.SystemBars
01-07 06:22:07.270 D/SystemUIService( 3198): running: com.android.systemui.statusbar.SystemBars@418c0328
001-07 06:22:07.290 D/SystemUIService( 3198): loading: class com.android.systemui.usb.StorageNotification
com.android.systemui.usb.StorageNotification@418c2780
01-07 06:22:07.300 I/fsck_msdos( 1326): ** Phase 4 - Checking for Lost Files
01-07 06:22:07.630 I/PackageManager( 3146): No secure containers on sdcard
01-07 06:22:07.630 I/ActivityManager( 3146): Start proc android.process.media for broadcast com.android.providers.downloads/.DownloadReceiver: pid=3256 uid=10006 gids={50006, 1028, 1015, 1023, 1024, 2001, 3003, 3007}
01-07 06:22:07.680 W/PackageManager( 3146): Not granting permission android.permission.DEVICE_POWER to package com.actions.explore (protectionLevel=2 flags=0x4088be45)
01-02 01:01:59.600 E/WifiConfigStore( 1627): Error parsing configurationjava.io.FileNotFoundException: /data/misc/wifi/ipconfig.txt: open failed: ENOENT (No such file or directory)
=======正常打印，导致引起FileNotFoundException是因为/data/misc/wifi/ipconfig.txt不存在
01-07 06:22:09.910 I/ActivityManager( 3146): Start proc com.android.phone for added application com.android.phone: pid=3359 uid=1001 gids={41001, 3002, 3001, 3003, 1028, 1015}
3.android第三阶段：启动完所需的核心服务后，启动launcher，进入home界面，android动画结束
01-07 06:22:09.920 I/ActivityManager( 3146): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10000000 cmp=com.android.launcher/com.android.launcher2.Launcher} from pid 0
01-07 06:22:09.960 I/LatinIME( 3315): Hardware accelerated drawing: false
01-07 06:22:10.010 I/ActivityManager( 3146): Start proc com.android.launcher for activity com.android.launcher/com.android.launcher2.Launcher: pid=3371 uid=10013 gids={50013}
01-02 01:03:15.880 W/System.err( 2522):