此文参考:/luzhenrong45/article/details/97393639
问题说明
项目在开机过程中出现无法正常启动，系统一直循环打印
D/dalvikvm( 358): GC_CONCURRENT freed 386K, 35% free 943K/1448K, paused 2ms+2ms, total 8ms
日志分析
--------- beginning of /dev/log/mainI/installd( 147): installd firing upI/toolbox ( 145): getprop ro.product.deviceI/Netd ( 143): Netd 1.0 startingI/toolbox ( 152): idW/InterfaceController( 143): Warning (dlopen failed: library "/system/lib/libnetcmdiface.so" not found) while opening the net interface command libraryE/DirectVolume( 142): Vold managed volumes must have auto mount point; ignoring /mnt/media_rw/extsdE/DirectVolume( 142): Vold managed volumes must have auto mount point; ignoring /mnt/media_rw/udisk--------- beginning of /dev/log/systemI/Vold ( 142): Vold 2.1 (the revenge) firing upD/Vold ( 142): Volume extsd state changing -1 (Initializing) -> 0 (No-Media)D/Vold ( 142): Volume udisk state changing -1 (Initializing) -> 0 (No-Media)D/MagDaemon( 155): init_sensorsI/toolbox ( 167): getprop user.kernellogI/toolbox ( 164): getprop user.reset.bt.wifi.infoI/SurfaceFlinger( 139): SurfaceFlinger is startingI/SurfaceFlinger( 139): SurfaceFlinger's main thread ready to run. Initializing graphics H/W...I/toolbox ( 178): getprop user.kernellogI/toolbox ( 182): getprop user.cmdlineI/toolbox ( 188): grep recovery_flagI/toolbox ( 192): getprop user.recoveryI/toolbox ( 189): dateI/recovery_flag.sh( 158): user.recovery is NULL!I/recovery_flag.sh( 158): recovery_flag.sh terminated by exit(1)I/toolbox ( 194): grep rever_typeI/toolbox ( 196): getprop user.reverseradar.typeI/reverse.sh( 159): REVERSET not changed!D/libEGL ( 139): loaded /system/lib/egl/libEGL_VIVANTE.soI/toolbox ( 199): grep languageI/toolbox ( 200): dd if=/dev/zero of=/dev/block/mmcblk3 seek=524292 bs=1 count=2048I/toolbox ( 203): grep backcar_typeI/toolbox ( 206): getprop user.languageI/toolbox ( 204): touchI/toolbox ( 209): touch _oopsI/toolbox ( 210): getprop persist.sys.languageI/toolbox ( 213): getprop user.backcar.typeI/toolbox ( 211): mount -t pstore pstore /root/I/backcar.sh( 157): Set backcar language: zhI/yantu.sh( 149): Writing 32-bit value 0x1C060601 to address 0x020C9010I/reverse.sh( 159): 2048+0 records inI/reverse.sh( 159): 2048+0 records outI/reverse.sh( 159): 2048 bytes transferred in 0.091 secs (22505 bytes/sec)I/toolbox ( 220): syncI/toolbox ( 219): chmod 777 /sys/class/hsaed531mc/cartype_info/cartypeI/toolbox ( 221): chmod 777 /sys/class/hsaed531mc/cartype_info/hwidI/toolbox ( 223): touch /data/bt_addr.iniI/backcar.sh( 157): TYPE not changed!D/MagDaemon( 155): couldn't find 'FreescaleAccelerometer' input deviceD/MagDaemon( 155): inital sensor errorI/toolbox ( 227): insmod /system/lib/modules/atmel_mxt_ts.koD/libEGL ( 139): loaded /system/lib/egl/libGLESv1_CM_VIVANTE.soI/toolbox ( 231): dd if=/cache/tmp of=/dev/block/mmcblk3 seek=524292 bs=1I/reverse.sh( 159): 402+0 records inI/reverse.sh( 159): 402+0 records outI/reverse.sh( 159): 402 bytes transferred in 0.017 secs (23647 bytes/sec)I/toolbox ( 236): syncI/toolbox ( 235): dd if=/dev/zero of=/dev/block/mmcblk3 seek=524292 bs=1 count=2048I/backcar.sh( 157): 2048+0 records inI/backcar.sh( 157): 2048+0 records outI/backcar.sh( 157): 2048 bytes transferred in 0.016 secs (128000 bytes/sec)I/toolbox ( 239): syncD/libEGL ( 139): loaded /system/lib/egl/libGLESv2_VIVANTE.soI/toolbox ( 242): dd if=/cache/tmp of=/dev/block/mmcblk3 seek=524292 bs=1I/backcar.sh( 157): 402+0 records inI/backcar.sh( 157): 402+0 records outI/backcar.sh( 157): 402 bytes transferred in 0.003 secs (134000 bytes/sec)I/toolbox ( 246): syncI/toolbox ( 248): dd if=/dev/block/mmcblk3boot1 bs=512 count=1I/toolbox ( 249): grep ^Already Written!$I/imx6.gralloc( 139): open gpu gralloc module!I/imx6.gralloc( 139): fb_device_open dispid:0, fb:0W/imx6.gralloc( 139): using (fd=19)W/imx6.gralloc( 139): id = DISP4 BGW/imx6.gralloc( 139): xres = 1280 pxW/imx6.gralloc( 139): yres = 720 pxW/imx6.gralloc( 139): xres_virtual = 1280 pxW/imx6.gralloc( 139): yres_virtual = 2160 pxW/imx6.gralloc( 139): bpp = 32W/imx6.gralloc( 139): r = 16:8W/imx6.gralloc( 139): g = 8:8W/imx6.gralloc( 139): b = 0:8W/imx6.gralloc( 139): width = 203 mm (160.157639 dpi)W/imx6.gralloc( 139): height = 114 mm (160.421051 dpi)W/imx6.gralloc( 139): refresh rate = 60.02 HzI/FslHwcomposer( 139): using fsl hwc!!!I/FslHwcomposer( 139): int hwc_device_open(const hw_module_t*, const char*, hw_device_t**),567I/FslHwcomposer( 139): using fsl hwc!I/FslHwcomposer( 139): fb0 is ldbI/FslHwcomposer( 139): deviceI/FslHwcomposer( 139): fb1 is overlay deviceW/FslHwcomposer( 139): open /sys/class/graphics/fb2 failedW/FslHwcomposer( 139): open /sys/class/graphics/fb3 failedW/FslHwcomposer( 139): open /sys/class/graphics/fb4 failedW/FslHwcomposer( 139): open /sys/class/graphics/fb5 failedI/FslHwcomposer( 139): hwcomposer: open framebuffer fb0I/imx6.gralloc( 139): fb_device_open dispid:0, fb:0I/imx6.gralloc( 139): display already initialized...I/FslHwcomposer( 139): int hwc_device_open(const hw_module_t*, const char*, hw_device_t**),426I/SurfaceFlinger( 139): Using composer version 1.3W/SurfaceFlinger( 139): no suitable EGLConfig found, trying a simpler queryI/SurfaceFlinger( 139): EGL informations:I/SurfaceFlinger( 139): vendor : AndroidI/SurfaceFlinger( 139): version : 1.4 Android META-EGLI/SurfaceFlinger( 139): extensions: EGL_KHR_get_all_proc_addresses EGL_ANDROID_presentation_time EGL_KHR_image EGL_KHR_image_base EGL_KHR_image_pixmap EGL_KHR_lock_surface EGL_KHR_gl_texture_2D_image EGL_KHR_gl_texture_cubemap_image EGL_KHR_gl_renderbuffer_image EGL_KHR_reusable_sync EGL_KHR_fence_sync EGL_KHR_create_context EGL_EXT_create_context_robustness EGL_ANDROID_image_native_buffer EGL_KHR_wait_sync EGL_ANDROID_recordableI/SurfaceFlinger( 139): Client API: OpenGL_ESI/SurfaceFlinger( 139): EGLSurface: 8-8-8-8, config=0x16W/linker ( 146): libfsl_jpeg_enc_arm11_elinux.so has text relocations. This is wasting memory and is a security risk. Please fix.I/SurfaceFlinger( 139): OpenGL ES informations:I/SurfaceFlinger( 139): vendor : Vivante CorporationI/SurfaceFlinger( 139): renderer : Vivante GC2000I/SurfaceFlinger( 139): version : OpenGL ES 3.0 V5.0.11.p8.41671I/SurfaceFlinger( 139): extensions: GL_EXT_debug_marker GL_OES_vertex_type_10_10_10_2 GL_OES_vertex_half_float GL_OES_element_index_uint GL_OES_mapbuffer GL_OES_vertex_array_object GL_OES_compressed_ETC1_RGB8_texture GL_OES_compressed_paletted_texture GL_OES_texture_npot GL_OES_rgb8_rgba8 GL_OES_depth_texture GL_OES_depth_texture_cube_map GL_OES_depth24 GL_OES_depth32 GL_OES_packed_depth_stencil GL_OES_fbo_render_mipmap GL_OES_get_program_binary GL_OES_fragment_precision_high GL_OES_standard_derivatives GL_OES_EGL_image GL_OES_EGL_image_external GL_OES_EGL_sync GL_OES_required_internalformat GL_OES_surfaceless_context GL_EXT_texture_type_2_10_10_10_REV GL_EXT_texture_filter_anisotropic GL_EXT_texture_format_BGRA8888 GL_EXT_read_format_bgra GL_EXT_multi_draw_arrays GL_EXT_frag_depth GL_EXT_discard_framebuffer GL_EXT_blend_minmax GL_EXT_multisampled_render_to_texture GL_EXT_robustness GL_VIV_direct_textureI/SurfaceFlinger( 139): GL_MAX_TEXTURE_SIZE = 8192I/SurfaceFlinger( 139): GL_MAX_VIEWPORT_DIMS = 8192E/cutils-trace( 139): Error opening trace file: Permission denied (13)E/libEGL ( 139): EGLBoolean eglSetSwapRectangleANDROID(EGLDisplay, EGLSurface, EGLint, EGLint, EGLint, EGLint):1590 error 3008 (EGL_BAD_DISPLAY)I/imx6.gralloc( 139): fb_device_open dispid:0, fb:0I/imx6.gralloc( 139): display already initialized...D/SurfaceFlinger( 139): Screen acquired, type=0 flinger=0x2b4e6008I/FslHwcomposer( 139): prepare: targetHandle is nullI/mediaserver( 146): ServiceManager: 0x2bf87640I/AudioFlinger( 146): Using default 3000 mSec as standby time.I/CameraService( 146): CameraService started (pid=146)I/CameraService( 146): Loaded "Freescale CameraHal Module" camera moduleI/FslCameraHAL( 146): Face Back Camera is ak8859, orient is 0I/FslCameraHAL( 146): Face Front Camera is 0, orient is 0I/FslCameraHAL( 146): Checking the camera ak8859I/FslCameraHAL( 146): Get sensor ak8859's dev path /dev/video0I/FslCameraHAL( 146): Camera ID 0: name ak8859, Facing 0, orientation 0, dev path /dev/video0I/AudioPolicyManagerBase( 146): loadAudioPolicyConfig() loaded /system/etc/audio_policy.confW/audio_hw_primary( 146): card 0, id ymu836audio ,driver ymu836-audio, name ymu836-audioW/audio_hw_primary( 146): out rate 44100W/audio_hw_primary( 146): in rate 44100, channels 1 format 0W/audio_hw_primary( 146): card 1, id ymu836saudio ,driver ymu836s-audio, name ymu836s-audioW/audio_hw_primary( 146): out rate 44100W/audio_hw_primary( 146): in rate 44100, channels 1 format 0I/AudioFlinger( 146): loadHwModule() Loaded primary audio interface from Freescale i.MX Audio HW HAL (audio) handle 1W/audio_hw_primary( 146): open output stream devices 2, format 1, channels 3, sample_rate 44100, flag 2W/audio_hw_primary( 146): opened out stream...735643512, type 1I/AudioFlinger( 146): HAL output buffer size 384 frames, normal mix buffer size 768 framesI/AudioMixer( 146): found effect "Multichannel Downmix To Stereo" from The Android Open Source ProjectE/MonoPipe( 146): Failed to fetch local time frequency when constructing a MonoPipe (res = -32). getNextWriteTimestamp calls will be non-functionalD/AndroidRuntime( 140):D/AndroidRuntime( 140): >>>>>> AndroidRuntime START com.android.internal.os.ZygoteInit <<<<<<D/AndroidRuntime( 140): CheckJNI is OFFI/AndroidRuntime( 140): JNI options: '-Xjniopts:warnonly'D/libEGL ( 267): loaded /system/lib/egl/libEGL_VIVANTE.soD/libEGL ( 267): loaded /system/lib/egl/libGLESv1_CM_VIVANTE.soD/libEGL ( 267): loaded /system/lib/egl/libGLESv2_VIVANTE.soE/cutils-trace( 267): Error opening trace file: Permission denied (13)I/imx6.gralloc( 267): open gpu gralloc module!E/BufferQueue( 139): [BootAnimation] dequeueBuffer: can't dequeue multiple buffers without setting the buffer countI/BootAnimation( 267): bool android::BootAnimation::video() startI/dalvikvm( 140): DexOpt: not all deps representedE/dalvikvm( 140): /system/framework/anwsdk.jar odex has stale dependenciesD/dalvikvm( 140): Trying to load lib libjavacore.so 0x0D/dalvikvm( 140): Added shared lib libjavacore.so 0x0D/dalvikvm( 140): Trying to load lib libnativehelper.so 0x0D/dalvikvm( 140): Added shared lib libnativehelper.so 0x0D/dalvikvm( 140): No JNI_OnLoad found in libnativehelper.so 0x0, skipping initD/dalvikvm( 140): Note: class Landroid/app/ActivityManagerNative; has 179 unimplemented (abstract) methodsE/memtrack( 140): Couldn't load memtrack module (No such file or directory)E/android.os.Debug( 140): failed to load memtrack module: -2I/SamplingProfilerIntegration( 140): Profiling disabled.E/Zygote ( 140): Bootopt(2) enabled: Class/Resource preloading will be disabled!D/ZZZ ( 140): Current timestamp(ms): 4179D/ZZZ ( 140): persist.bolt.enable = falseD/ZZZ ( 140): persist.bolt.preload.defer = falseD/ZZZ ( 140): persist.bolt.preload.nores = falseD/ZZZ ( 140): persist.bolt.display.force = falseD/ZZZ ( 140): persist.bolt.ams.persist = falseD/ZZZ ( 140): persist.bolt.sss.priority = falseD/ZZZ ( 140): persist.bolt.sss.mthread = falseD/ZZZ ( 140): persist.bolt.pms.scan = falseD/ZZZ ( 140): persist.bolt.pms.scan.async = falseD/ZZZ ( 140): persist.bolt.pms.scan.early = falseD/ZZZ ( 140): persist.bolt.sysui.nokeyguard = falseD/ZZZ ( 140): persist.bolt.sysui.preload = falseD/ZZZ ( 140): persist.bolt.sysui.car = falseD/ZZZ ( 140): persist.bolt.prestart.launcher = falseD/ZZZ ( 140): persist.bolt.launcher.priority = falseD/ZZZ ( 140): persist.bolt.disable.wallpaper = falseD/ZZZ ( 140): persist.bolt.stop.bootanim = falseD/ZZZ ( 140): persist.bolt.preload.drawable = falseD/ZZZ ( 140): persist.bolt.prestart.autocore = falseD/ZZZ ( 140): persist.bolt.power.state = falseE/cutils-trace( 140): Error opening trace file: No such file or directory (2)D/dalvikvm( 140): GC_EXPLICIT freed 32K, 7% free 492K/528K, paused 0ms+0ms, total 3msD/dalvikvm( 140): GC_EXPLICIT freed <1K, 7% free 492K/528K, paused 0ms+0ms, total 2msD/dalvikvm( 140): GC_EXPLICIT freed <1K, 7% free 492K/528K, paused 1ms+0ms, total 2msI/dalvikvm( 140): System server process 358 has been createdI/Zygote ( 140): Accepting command socket connectionsD/SensorService( 358): nuSensorService starting...I/SystemServer( 358): Entered the Android system server!E/ ( 358): Couldn't find 'FreescaleAccelerometer' input deviceE/ ( 358): Couldn't open /dev/mma8x5x (No such file or directory)E/ ( 358): Can`t find the Acc sensor!E/ ( 358): Couldn't find 'eCompass' input deviceE/ ( 358): Can`t find the mag sensor!E/ ( 358): Couldn't find 'isl29023 light sensor' input deviceI/SensorService( 358): Freescale 3-axis AccelerometerI/SensorService( 358): Freescale 3-axis Magnetic field sensorI/SensorService( 358): Freescale Orientation sensorI/SensorService( 358): ISL29023 Light sensorD/SensorService( 358): Max socket buffer size 163840D/SensorService( 358): nuSensorService thread starting...I/installd( 147): new connectionI/SystemServer( 358): Waiting for installd to be ready.I/Installer( 358): connecting...I/SystemServer( 358): Power ManagerE/SWITCHPROFILE( 358): setprop: sys.interactive = activeI/SystemServer( 358): Activity ManagerI/ActivityManager( 358): Memory class: 64D/dalvikvm( 358): GC_CONCURRENT freed 73K, 12% free 835K/944K, paused 2ms+0ms, total 6msW/BatteryStatsImpl( 358): Couldn't get kernel wake lock statsD/dalvikvm( 358): GC_CONCURRENT freed 233K, 21% free 1027K/1296K, paused 16ms+1ms, total 23msW/UsageStats( 358): Usage stats version changed; droppingD/dalvikvm( 358): GC_CONCURRENT freed 470K, 35% free 945K/1448K, paused 1ms+0ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 388K, 35% free 943K/1448K, paused 2ms+1ms, total 7msV/NatController( 143): runCmd(/system/bin/iptables -F natctrl_FORWARD) res=0V/NatController( 143): runCmd(/system/bin/iptables -A natctrl_FORWARD -j DROP) res=0V/NatController( 143): runCmd(/system/bin/iptables -t nat -F natctrl_nat_POSTROUTING) res=0V/NatController( 143): runCmd(/system/bin/ip rule flush) res=0V/NatController( 143): runCmd(/system/bin/ip -6 rule flush) res=0V/NatController( 143): runCmd(/system/bin/ip rule add from all lookup default prio 32767) res=0V/NatController( 143): runCmd(/system/bin/ip rule add from all lookup main prio 32766) res=0V/NatController( 143): runCmd(/system/bin/ip -6 rule add from all lookup default prio 32767) res=0V/NatController( 143): runCmd(/system/bin/ip -6 rule add from all lookup main prio 32766) res=0V/NatController( 143): runCmd(/system/bin/ip route flush cache) res=0D/dalvikvm( 358): GC_CONCURRENT freed 384K, 35% free 943K/1448K, paused 1ms+1ms, total 6msV/NatController( 143): runCmd(/system/bin/iptables -F natctrl_tether_counters) res=1V/NatController( 143): runCmd(/system/bin/iptables -X natctrl_tether_counters) res=1V/NatController( 143): runCmd(/system/bin/iptables -N natctrl_tether_counters) res=0D/dalvikvm( 358): GC_CONCURRENT freed 384K, 35% free 943K/1448K, paused 1ms+0ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 384K, 35% free 943K/1448K, paused 2ms+1ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 384K, 35% free 943K/1448K, paused 1ms+1ms, total 6msD/dalvikvm( 358): GC_CONCURRENT freed 384K, 35% free 943K/1448K, paused 1ms+0ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 384K, 35% free 943K/1448K, paused 2ms+1ms, total 7msD/MDnsDS ( 143): MDnsSdListener::Hander starting upD/MDnsDS ( 143): MDnsSdListener starting to monitorD/MDnsDS ( 143): Going to poll with pollCount 1D/dalvikvm( 358): GC_CONCURRENT freed 386K, 35% free 943K/1448K, paused 2ms+2ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 390K, 35% free 943K/1448K, paused 1ms+2ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 389K, 35% free 944K/1448K, paused 1ms+1ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 1ms+1ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 2ms+0ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 2ms+1ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 943K/1448K, paused 2ms+2ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 384K, 35% free 943K/1448K, paused 1ms+1ms, total 6msD/dalvikvm( 358): GC_CONCURRENT freed 389K, 35% free 944K/1448K, paused 1ms+1ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 943K/1448K, paused 1ms+0ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 2ms+1ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 943K/1448K, paused 2ms+1ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 1ms+0ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 943K/1448K, paused 1ms+2ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 389K, 35% free 943K/1448K, paused 2ms+1ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 943K/1448K, paused 2ms+2ms, total 9msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 1ms+1ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 1ms+1ms, total 8msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 2ms+0ms, total 7msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 2ms+1ms, total 9msD/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 2ms+0ms, total 7ms
通过日志信息，根据
D/dalvikvm( 358): GC_CONCURRENT freed 393K, 35% free 944K/1448K, paused 1ms+1ms, total 8ms分析:
PID 358 通过PS查询可知问题出在system_server:
root@sabresd_6dq_wh_leinuo:/ # ps | grep 358system 358 140 840304 38768 ffffffff 2b0f7834 S system_server
top查询system_server系统占用：
root@sabresd_6dq_wh_leinuo:/ # top | grep system_server359 0 51% S 62 840304K 38680K fg system system_server
经过与正常日志对比发现，出现异常时发现多了一行打印：
W/UsageStats( 358): Usage stats version changed; dropping
代码跟踪
UsageStatsService 是Android一个私有service，主要作用是收集用户使用每一个APP的频率、使用时常等，用于统计应用程序的使用情况。
该service 是在ActivityManagerService服务中启动的：
framework/base/services/java/com/android/server/am/ActivityManagerService.java
private ActivityManagerService() {Slog.i(TAG, "Memory class: " + ActivityManager.staticGetMemoryClass());mFgBroadcastQueue = new BroadcastQueue(this, "foreground", BROADCAST_FG_TIMEOUT, false);mBgBroadcastQueue = new BroadcastQueue(this, "background", BROADCAST_BG_TIMEOUT, true);mBroadcastQueues[0] = mFgBroadcastQueue;mBroadcastQueues[1] = mBgBroadcastQueue;mServices = new ActiveServices(this);mProviderMap = new ProviderMap(this);File dataDir = Environment.getDataDirectory();File systemDir = new File(dataDir, "system");systemDir.mkdirs();mBatteryStatsService = new BatteryStatsService(new File( systemDir, "batterystats.bin").toString());mBatteryStatsService.getActiveStatistics().readLocked();mBatteryStatsService.getActiveStatistics().writeAsyncLocked();mOnBattery = DEBUG_POWER ? true: mBatteryStatsService.getActiveStatistics().getIsOnBattery();mBatteryStatsService.getActiveStatistics().setCallback(this);mProcessStats = new ProcessStatsService(this, new File(systemDir, "procstats"));mUsageStatsService = new UsageStatsService(new File(systemDir, "usagestats").toString());mAppOpsService = new AppOpsService(new File(systemDir, "appops.xml"));mGrantFile = new AtomicFile(new File(systemDir, "urigrants.xml"));mHeadless = "1".equals(SystemProperties.get("ro.config.headless", "0"));// User 0 is the first and only user that runs at boot.mStartedUsers.put(0, new UserStartedState(new UserHandle(0), true));mUserLru.add(Integer.valueOf(0));updateStartedUserArrayLocked();GL_ES_VERSION = SystemProperties.getInt("ro.opengles.version",ConfigurationInfo.GL_ES_VERSION_UNDEFINED);mConfiguration.setToDefaults();mConfiguration.setLocale(Locale.getDefault());......
搜索错误信息：Usage stats version changed; dropping
发现在文件：framework/base/services/java/com/android/server/am/UsageStatsService.java中：
private void readStatsFLOCK(File file) throws IOException {Parcel in = getParcelForFile(file);int vers = in.readInt();if (vers != VERSION) {Slog.w(TAG, "Usage stats version changed; dropping"); return;} int N = in.readInt();while (N > 0) { N--; String pkgName = in.readString();if (pkgName == null) {break;} if (localLOGV) Slog.v(TAG, "Reading package #" + N + ": " + pkgName);PkgUsageStatsExtended pus = new PkgUsageStatsExtended(in);synchronized (mStatsLock) {mStats.put(pkgName, pus);} } }
UsageStatsService会在/data/system/usagestats/目录下保存一些记录app使用频率和时长的数据文件。类似如下：
root@sabresd_6dq_wh_leinuo:/data/system/usagestats # ls -l-rw------- system system 0 -08-17 16:30 usage-0817-rw------- system system 340 -09-22 14:15 usage-0921-rw------- system system -01-01 12:00 usage-0922-rw------- system system 880 2024-05-08 23:00 usage-20300423-rw------- system system 0 -10-19 00:07 usage-history.xml
其中：
/data/system/usagestats/usage-日期” 文件记录的当天的使用记录的数据
/data/system/usagestats/usage-history.xml文件中读取每个APP中每个Activity最后启动的时间
UsageStatsService服务启动的时候，会去读取并解析这些文件。一般情况下，UsageStatsService取到的ver与 VERSION(常量1007)，通过增加log，发现这里取到的ver居然为0，/data/system/usagestats/usage-history.xml文件，为空文件零字节的！
猜想和验证
猜想：会不会是 system_server初始化过程中，UsageStatService解析这些零字节文件时发生了文件操作异常？
验证：使用 lsof 命令查看出问题时data分区所有被打开的文件，发现其中就有usage-history.xml ！并且操作该文件的进程恰恰就是system_server
root@android:/data/system/usagestats #lsof| grep datasystem_se 1283 system 54 ??? ??? ??? ??? /data/system/usagestats/usage-history.xml
问题定位
到这里基本可以确定是system_server 启动过程中在读写 usage-history.xml 文件时出了问题。但是如果是简单的文件操作错误，最多是报个crash，理论上CPU占用率不应该那么高。除非是文件操作过程中发生死锁或者死循环之类的致命错误。
查了代码，UsageStatsService服务会在多个地方操作到usage-history.xml 文件，单纯从代码上看，并不能快速确定出总理 的地方。
或许可以看看 system_server的调用堆栈，兴许可以给我们留下一些线索…
查看进程堆栈，一种简单而实用的方法就是使用Android自带的DDMS工具。打开DDMS, 选中需要查看的进程号，这里选择的自然是 system_server (进程号为1283)，UsageStatsService是由ActivityManager启动的，因此先选中ActivityManager，接下来就查看相应的调用堆栈了。
从函数中调用堆栈信息中，可以看到UsageStatsService相关的堆栈停在了readHistoryStatsFLOCK()
readHistoryStatsFLOCK(AtomicFile file)函数主要负责解析我们前面说到的usage-history.xml文件。
Android4.4 XML的解析
在JAVA的世界里，解析xml文件有多种方式，不同的解析方式有着各自的优缺点和适用环境。在Android中常见的XML解析器分别为SAX解析器、DOM解析器以及PULL解析器。
看代码，知道上面使用的是PULL的方式来解析xml文件的，PULL技术是基于事件类型的解析，基本的事件类型有 5 个：
START_DOCUMENT (常量0，标记文档的开始)
START_TAG (常量2，标记一个标签的开始)
TEXT (常量4，标记一个标签的内容)
END_TAG (常量3，标记一个标签的结束)
END_DOCUMENT (常量1，标记文档的结束)
使用 parser.next() 可以进入下一个元素并触发相应事件。现在，再来看看刚才那段代码：
while (eventType != XmlPullParser.START_TAG) {eventType = parser.next();}
从代码上分析，这里用了一个while循环，想要实现的功能是，一旦识别到XML的标签事件（START_TAG），便退出等待循环，开始usage-history.xml标签内容的解析工作。
但是，此处该码有一个致命的问题：如果待解析的XML文件中到达文件结尾时，还解析不到START_TAG事件，便会陷入死循环当中！
而一旦陷在while死循环里面，system_server便无法往下继续启动
其他系统服务，因而不会等到系统ready后通知系统进入桌面。于是便出现系统开机后一直停留在开机动画播放阶段，不断循环的现象！
而前面我们说到，该设备usage-history.xml是个零字节空文件，因此问题便出在这里了！
问题修复
知道原因，那么，便知道怎么修改了，一旦解析到达xml文件末尾，还解析不到
START_TAG 事件，就应该主动退出while循环。
- while (eventType != XmlPullParser.START_TAG) { + //Danny： Fix empty xml file cause death cycle+ while (eventType != XmlPullParser.START_TAG && eventType != XmlPullParser.END_DOCUMENT) {eventType = parser.next();}
查看了各个历史版本，Android4.4以更低的版本皆存在这样的隐患问题，而Android5.0之后，由于UsageStatsService机制改变，因此已经修复该问题。
usage-history.xml一般情况下都会有内容，因此，触发到死循环的概率很低。但有些情况也可能导致 usage-history.xml为零字节：
比如用户强行断电情况下便可能导致IO读写无法正常结束，引发零字节问题。
比如 flash 硬件质量问题
比如Android Ext4文件系统的延迟分配（delalloc）功能，该功能网上反馈有有比较大的问题，可能造成数据丢失、0长度等问题，
PS: 解决此类问题的方案就是在分区挂载的时候，禁用延迟分配功能，也就是开启 nodelalloc 选项。
杯弓蛇影
解决完这个问题后，留了一心眼，重新搜索了整个Android4.4的系统源码，发现还有几处代码也是采用 “while (eventType != XmlPullParser.START_TAG)” 这样的写法，并且没有主动判断跳出循环。这些地方也是埋了坑的，哪天不小心就会陷入这些死循环，导致另一个开机白屏问题。因此，也是需要把这些隐患一块修复掉！
diff --git a/services/java/com/android/server/am/CompatModePackages.java b/services/java/com/android/server/am/CompatModePackages.javaindex 59e6787..470ecea 100755--- a/services/java/com/android/server/am/CompatModePackages.java+++ b/services/java/com/android/server/am/CompatModePackages.java@@ -64,7 +64,8 @@ public final class CompatModePackages {XmlPullParser parser = Xml.newPullParser();parser.setInput(fis, null);int eventType = parser.getEventType();- while (eventType != XmlPullParser.START_TAG) {+ /* Fixed empty xml file cause death cycle */+ while (eventType != XmlPullParser.START_TAG && eventType != XmlPullParser.END_DOCUMENT) {eventType = parser.next();}String tagName = parser.getName();diff --git a/services/java/com/android/server/am/UsageStatsService.java b/services/java/com/android/server/am/UsageStatsService.javaindex e96d8b1..40e43cb 100755--- a/services/java/com/android/server/am/UsageStatsService.java+++ b/services/java/com/android/server/am/UsageStatsService.java@@ -396,8 +396,9 @@ public final class UsageStatsService extends IUsageStats.Stub {XmlPullParser parser = Xml.newPullParser();parser.setInput(fis, null);int eventType = parser.getEventType();- while (eventType != XmlPullParser.START_TAG) {- eventType = parser.next();+ /* Fixed empty xml file cause death cycle */+ while (eventType != XmlPullParser.START_TAG && eventType != XmlPullParser.END_DOCUMENT) {+ eventType = parser.next();}String tagName = parser.getName();diff --git a/services/java/com/android/server/am/UsageStatsService.java b/services/java/com/android/server/am/UsageStatsService.javaindex e96d8b1..40e43cb 100755--- a/services/java/com/android/server/am/UsageStatsService.java+++ b/services/java/com/android/server/am/UsageStatsService.java@@ -396,8 +396,9 @@ public final class UsageStatsService extends IUsageStats.Stub {XmlPullParser parser = Xml.newPullParser();parser.setInput(fis, null);int eventType = parser.getEventType();- while (eventType != XmlPullParser.START_TAG) {- eventType = parser.next();+ /* Fixed empty xml file cause death cycle */+ while (eventType != XmlPullParser.START_TAG && eventType != XmlPullParser.END_DOCUMENT) {+ eventType = parser.next();}String tagName = parser.getName();if ("usage-history".equals(tagName)) {diff --git a/services/java/com/android/server/content/SyncStorageEngine.java b/services/java/com/android/server/content/SyncStorageEngine.javaindex 781280e..e8c45ff 100755--- a/services/java/com/android/server/content/SyncStorageEngine.java+++ b/services/java/com/android/server/content/SyncStorageEngine.java@@ -1697,7 +1697,8 @@ public class SyncStorageEngine extends Handler {XmlPullParser parser = Xml.newPullParser();parser.setInput(fis, null);int eventType = parser.getEventType();- while (eventType != XmlPullParser.START_TAG) {+ /* Fixed empty xml file cause death cycle */+ while (eventType != XmlPullParser.START_TAG && eventType != XmlPullParser.END_DOCUMENT) {eventType = parser.next();}String tagName = parser.getName();(END)
