JAVA高级面试进阶训练营视频教程

admin

个人原创，转载请注明出处

 

自毕业以来已经从事两年Android Framewok开发，到如今才积累一点点能够拿出来分享的东西，今天记录一篇关于手机循环重启问题的分析和解决过程。 

问题描述：

　　一部被退回返修的手机，搭载Android N OS，手机开机到出现systemui界面即立刻重启，如此循环往复直至电量耗尽。

对问题进行合理猜测：

　　手机重启一般可以分两大类，

　　　　1 上层重要进程crash，比如system_server进程挂掉，watchdog重启，或者其他进程crash把system_server进程带挂了。

　　　　2 kernel 导致的重启，比如空指针，非法地址等。

　　既然能够开机到systemui显示，大体可以先判断为system_server发生了Crash导致手机重启。

　　抓log观察一下，这里有必要介绍一点adb shell dumpsys的知识，

　　dumpsys activity //查询AMS服务相关信息

　　dumpsys window //查询WMS服务相关信息

　　dumpsys cpuinfo //查询CPU情况

　　dumpsys meminfo //查询内存情况

　　比如我经常使用的两个dumpsys命令是：

　　adb shell dumpsys activity top 和 adb shell pm path "packageName"

　　adb shell dumpsys activity top 命令可以查看当前手机最上层窗口显示界面所属的应用的包名，拿到报名之后就可以通过adb shell pm path "packageName"拿到它的安装目录。

　　好了，言归正传，分析手机循环重启问题我们需要用到另一个dumpsys 命令：adb shell dumpsys dropbox -p

　　Android dropbox提供了一种保存日志的机制，支持将内核、Native、Java多种日志保存在"/data/system/dropbox"目录中。用以上命令就可以将这种日志提取出来，当然也可以用adb pull /data/system/dropbox提取。此处我们用grep过滤一下log

　　adb shell dumpsys dropbox -p | tee log1.txt | grep FATAL

　　06-19 09:15:14.858 E/AndroidRuntime( 1170): *** FATAL EXCEPTION IN SYSTEM PROCESS: notification-sqlite-log

　　此处注意 "FATAL EXCEPTION IN SYSTEM PROCESS: notification-sqlite-log"

 

　　那么打开log1.txt,搜索"FATAL EXCEPTION IN SYSTEM PROCESS: notification-sqlite-log"

06-19 09:15:14.845 E/SQLiteLog( 1170): (2570) os_unix.c:32626: (13) unlink(/data/system/notification_log.db-journal) -
06-19 09:15:14.845 E/SQLiteLog( 1170): (2570) disk I/O error
06-19 09:15:14.830 W/notification-sq( 1396): type=1400 audit(0.0:76): avc: denied { write } for name="system" dev="mmcblk0p27" ino=360449 scontext=u:r:system_server:s0 tcontext=u:object_r:unlabeled:s0 tclass=dir permissive=0
06-19 09:15:14.848 D/WifiService( 1170): onReceive, action:android.net.wifi.WIFI_STATE_CHANGED
06-19 09:15:14.857 E/SQLiteDatabase( 1170): Failed to open database '/data/system/notification_log.db'.
06-19 09:15:14.857 E/SQLiteDatabase( 1170): android.database.sqlite.SQLiteDiskIOException: disk I/O error (code 2570): , while compiling: PRAGMA journal_mode
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnection.acquirePreparedStatement(SQLiteConnection.java:898)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnection.executeForString(SQLiteConnection.java:643)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnection.setJournalMode(SQLiteConnection.java:325)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnection.setWalModeFromConfiguration(SQLiteConnection.java:299)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:220)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:198)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:838)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:823)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:716)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:664)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:223)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:163)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at com.android.server.notification.NotificationUsageStats$SQLiteLog.writeEvent(NotificationUsageStats.java:1212)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at com.android.server.notification.NotificationUsageStats$SQLiteLog.-wrap0(NotificationUsageStats.java)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at com.android.server.notification.NotificationUsageStats$SQLiteLog$1.handleMessage(NotificationUsageStats.java:1065)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.os.Handler.dispatchMessage(Handler.java:110)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.os.Looper.loop(Looper.java:203)
06-19 09:15:14.857 E/SQLiteDatabase( 1170): at android.os.HandlerThread.run(HandlerThread.java:61)

06-19 09:15:14.858 E/AndroidRuntime( 1170): *** FATAL EXCEPTION IN SYSTEM PROCESS: notification-sqlite-log
06-19 09:15:14.858 E/AndroidRuntime( 1170): android.database.sqlite.SQLiteDiskIOException: disk I/O error (code 2570): , while compiling: PRAGMA journal_mode
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnection.nativePrepareStatement(Native Method)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnection.acquirePreparedStatement(SQLiteConnection.java:898)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnection.executeForString(SQLiteConnection.java:643)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnection.setJournalMode(SQLiteConnection.java:325)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnection.setWalModeFromConfiguration(SQLiteConnection.java:299)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:220)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:198)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:838)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:823)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:716)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:664)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:223)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:163)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at com.android.server.notification.NotificationUsageStats$SQLiteLog.writeEvent(NotificationUsageStats.java:1212)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at com.android.server.notification.NotificationUsageStats$SQLiteLog.-wrap0(NotificationUsageStats.java)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at com.android.server.notification.NotificationUsageStats$SQLiteLog$1.handleMessage(NotificationUsageStats.java:1065)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.os.Handler.dispatchMessage(Handler.java:110)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.os.Looper.loop(Looper.java:203)
06-19 09:15:14.858 E/AndroidRuntime( 1170): at android.os.HandlerThread.run(HandlerThread.java:61)

注意到进程pid:1170,FATAL EXCEPTION IN SYSTEM PROCESS: notification-sqlite-log,system_server进程在此处Crash了，这也就导致手机循环重启直至电量耗尽。

再往前看一点，就会发现真正挂掉的原因是Failed to open database '/data/system/notification_log.db'.notification_log.db出现了问题拖死了system_server。

继续看android.database.sqlite.SQLiteDiskIOException: disk I/O error (code 2570): , while compiling: PRAGMA journal_mode，error code是非常重要的信息，查询一下这个错误码：

(2570) SQLITE_IOERR_DELETE

The SQLITE_IOERR_UNLOCK error code is an extended error code for SQLITE_IOERR indicating an I/O error within xDelete method on the sqlite3_vfs object.

这个error code就证明是文件格式被损坏了，Sqlite在解析数据库文件的时候出现了致命错误。如何证明这个判断呢？我们可以注意到数据库文件所处的路径在/data/system/notification_log.db-journal，也就是本博文贴出的log的第一行：

06-19 09:15:14.845 E/SQLiteLog( 1170): (2570) os_unix.c:32626: (13) unlink(/data/system/notification_log.db-journal) - 

我们用正常的文件去替换掉该路径的notification_log.db和notification_log.db-journal就可以证明我的判断，果然是文件损坏，替换文件之后手机就恢复正常了，但是与这个问题相关的代码是谷歌的源码，并且在数据库并发方面做了加锁保护，又是用户退机，没办法找出文件被损坏的根本原因。但是我们可以针对文件损坏做一些保护机制，比如在发生这种循坏重启时五次之后就进入恢复出厂设置模式，或者每隔一段时间对文件进行备份，当出现这种情况是就进行文件替换，将正常的文件拷贝到该目录。

再多说一点.db-journal文件，这个文件主要用于sqlite事务回滚机制，在事务开始时产生，在事务结束时删除；当程序发生崩溃或者系统断电时该文件将留在磁盘上，以便下次程序运行时进行事务回滚。本身就是一个保护机制，但是不幸的是这个文件格式损坏导致了手机循环重启。至此问题分析总结完毕，真实的分析过程并没有博客中的来的顺利。