开机启动慢的原因分析

        最近的项目开机启动花了40多秒，正常开机只需要28秒就能开机起来。

内核的启动我没有去分析，另一个同事分析的。我主要是分析从SystemServer启来到开机动画结束显示解锁界面的这段时间，也就是开机动画的第三个动画开始到结束这段时间，这是个比较耗时阶段，一般都在17秒左右(见过牛B的手机，只需5秒)。

        SystemServer分两步执行：init1和init2。init1主要是初始化native的服务，代码在system_init.cpp的system_init，初始化了SurfaceFlinger和SensorService这两个native的服务。init2启动的是java的服务，比如ActivityManagerService、WindowManagerService、PackageManagerService等，在这个过程中PackageManagerService用的时间最长，因为PackageManagerService会去扫描特定目录下的jar包和apk文件。

        在开机时间需要40多秒的时，从Log上可以看到，从SurfaceFlinger初始化到动画结束，要27秒左右的时间,即从SurfaceFlinger::init的LOGI("SurfaceFlinger is starting")这句Log到void SurfaceFlinger::bootFinished()的LOGI("Boot is finished (%ld ms)", long(ns2ms(duration)) )，需要27秒左右的时间，这显然是太长了，但到底是慢在哪了呢？应该在个中间的点，二分一下，于是想到了以启动服务前后作为分隔：是服务启动慢了，还是在服务启动后的这段时间慢？以ActivityManagerService的Slog.i(TAG, "System now ready")的这句Log为分割点，对比了一下，在从SurfaceFlinger is starting到System now ready多了7秒左右的时间，这说明SystemServer在init1和init2过程中启动慢了，通过排查，发现在init1启动的时候，花了7秒多的时间，也就是system_init的LOGI("Entered system_init()")到LOGI("System server: starting Android runtime.\n")这段时间用了7秒多，而正常情况是400毫秒便可以初始化完，通过添加Log看到，在SensorService启动时，用了比较长的时间。

        不断的添加Log发现，在启动SensorService时候，关闭设备文件变慢了，每次关闭一个/dev/input/下的设备文件需要100ms左右，而SensorService有60~70次的关闭文件，大概有7s左右的时间。
调用流程是:
frameworks/base/cmds/system_server/library/system_init.cpp:  system_init->SensorService::instantiate
frameworks/native/services/sensorservice/SensorService.cpp:  void SensorService::onFirstRef()->SensorDevice& dev(SensorDevice::getInstance())
hardware/libsensors/SensorDevice.cpp:    SensorDevice::SensorDevice()->sensors_open
hardware/libsensors/sensors.cpp:         open_sensors->sensors_poll_context_t
sensors_poll_context_t执行打开每个传感器设备时，遍历/dev/input/目录下的设备文件，以匹配当前需要打开的设备，遍历文件是在
hardware/libsensors/SensorBase.cpp的openInput下实现，如果打开的设备文件不是正在打开的设备文件，会执行下面语句的else部分：
   if (!strcmp(name, inputName)) {
       strcpy(input_name, filename);
       break;
   } else {
close(fd);
       fd = -1;
   }
close每次需要100ms左右，每次打开传感器部分都执行去这样的操作，导致了在这有大概7s左右的延迟。

优化完这段时间后，系统启动变快了7秒，但还是慢，因为对比可以发现：

开机28秒：

04-16 16:14:22.205   140   343 I SurfaceFlinger: Using composer version 1.0
04-16 16:14:34.167   527   542 I ActivityManager: System now ready
04-16 16:14:39.089   140   605 I SurfaceFlinger: Boot is finished (16985 ms)

开机34秒：

04-18 15:32:55.565 I/SurfaceFlinger(  242): SurfaceFlinger is starting
04-18 15:33:05.214 I/ActivityManager(  622): System now ready
04-18 15:33:17.658 I/SurfaceFlinger(  242): Boot is finished (22091 ms)

可见还是慢了6秒。但这6秒慢在了似乎是在服务启动后的时间，这个时候比较难分析了，原因是这是所有的服务起来了，而且发出了bootcomplete广播，应用也开始起来，但还没用解锁，开始以为是Launcher起来慢了，但换了一个Google原始的Launcher进去，并没有变快。

       我们用两个版本的手机，W制式的跟TD的，过来几天发现TD的手机比W的开机快，而且TD的28秒左右能起来，但W的却要34秒，问了一下驱动的同事，W跟TD的并没有什么区别，所以除了Modem不一样以外，其他的都一样。找了一天，依然毫无结果。从Log中看，都只这慢一点，那慢一点，只有在Packmanager在扫描包的过程中，W+GSM需要6秒左右的时间，而TD+GSM只需要3秒左右的时间，但也不至于花费6秒的时间。但软件版本是一样的，猜测是硬件的问题，但硬件都是一样的，除了Modem不一样以外，开始怀疑Modem，W+GSM是正常的开机模式，而TD+GSM却是在mbp模式下开机的，弄成一样的开机模式，依然没有改变两个开机时间。到最才发现W的手机用的是16G的EMMC，而TD的手机用的是32G的EMMC，而且32G的EMMC比16G的EMMC读写速度快，以为找到了原因，结果很失望，通过电子的同事，把EMMC对换了一下，开机速度还是没有变化，快的还是快，慢的还是这么慢，晕，白高兴了一场，但至少也发现了EMMC读写速度是不一样的，至少不是一无所获。折腾了一天，也就得到个这样的结果！！！

        过来一段时间以后，发现W的手机也变好了，28秒就能开机起来了，这是多么兴奋的是呀，不用解，问题就好了！可惜好景不长，没过多久，发现W的手机开机时间又变回33秒了，这还真让人郁闷，于是用抓Log看下，结果就诧异了，从SurfaceFlinger is starting到Boot is finished用是时间还是17秒左右，并没有变长呀！这是什么原因呢？同过实时的抓取LOG发现，28秒能开机起来的时候，Boot is finished这句LOG一打出，解到了解锁界面，但33秒是，却还等了一会才有解锁界面，难怪！一问，才知道他们在Boot is finished加了一句usleep(5*1000*1000)，原因是不这样做，解锁在开机起来后滑不动或者会卡顿，所以加了5秒的延迟。这我们当然是不同意的了！

       一个开机启动折腾了将近一个月，时快试慢，希望以后别这边慢，能够保持这样的速度。虽然汗水中伴着有失望、有痛苦，但自己还是学到了东西，至少知道做事情一定要坚持，面对问题时，视野一定要开阔，要考虑各种情况。