【Android12】Android性能调优工具SystemServerTiming日志

Android性能调优工具SystemServerTiming日志

性能优化、稳定性优化是Android系统优化的两大方面，对于性能调试Android提供了很多工具，比如：bootchart、systrace、perfboot、log、dmsg等等。

SystemServerTiming是Android原生系统中一个日志标签，也就是tag为SystemServerTiming的日志，这类日志信息会输出到Logd和Trace系统中。可以通过Android logcat 或者抓取Systrace的方式取得。

SystemServerTiming主要用于记录SystemServer中启动各种服务的耗时信息。在性能优化分析的场景下，利用该Log我们分析出SystemServer中各个服务在启动性能上是否存异常，特别是在SystemServer中自定义追加的Service。

SystemServerTiming日志的一段例子

# 示意log日志
11-20 23:58:20.766 21530 21530 I SystemServerTiming: InitBeforeStartServices
.................. 21530 21530 I SystemServerTiming: StartServices
.................. 21530 21530 I SystemServerTiming: startBootstrapServices
.................. 21530 21530 I SystemServerTiming: StartWatchdog
.................. 21530 21530 I SystemServerTiming: ReadingSystemConfig
.................. 21530 21530 I SystemServerTiming: PlatformCompat
.................. 21530 21530 I SystemServerTiming: StartFileIntegrityService
.................. 21530 21530 I SystemServerTiming: StartInstaller
.................. 21530 21530 I SystemServerTiming: DeviceIdentifiersPolicyService
.................. 21530 21530 I SystemServerTiming: UriGrantsManagerService
.................. 21530 21530 I SystemServerTiming: StartPowerStatsService
.................. 21530 21530 I SystemServerTiming: StartIStatsService
.................. 21530 21530 I SystemServerTiming: MemtrackProxyService
# 非User编译模式下，会输出统计每个阶段耗时的Log
.................. 21530 21530 I SystemServerTiming: InitBeforeStartServices took to complete: ***ms
...
.................. 21530 21530 I SystemServerTiming: startCoreServices
...
.................. 21530 21530 I SystemServerTiming: startOtherServices
.................. 21530 21530 I SystemServerTiming: SecondaryZygotePreload
...
.................. 21530 21530 I SystemServerTiming: StartSystemUI

SystemServerTiming日志的源码实现
TimingsTraceAndSlog.java源文件中，定义了SystemServerTiming日志标签，并通过Slog(输出到Logd的System分区)和Trace实现日志的输出。
源码路径：/frameworks/base/services/core/java/com/android/server/utils/TimingsTraceAndSlog.java

/** Copyright (C) 2019 The Android Open Source Project** Licensed under the Apache License, Version 2.0 (the "License");* you may not use this file except in compliance with the License.* You may obtain a copy of the License at**      http://www.apache.org/licenses/LICENSE-2.0** Unless required by applicable law or agreed to in writing, software* distributed under the License is distributed on an "AS IS" BASIS,* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.* See the License for the specific language governing permissions and* limitations under the License.*/
package com.android.server.utils;import android.annotation.NonNull;
import android.os.Trace;
import android.util.Slog;
import android.util.TimingsTraceLog;/*** Helper class for reporting boot and shutdown timing metrics, also logging to {@link Slog}.*/
public final class TimingsTraceAndSlog extends TimingsTraceLog {/*** Tag for timing measurement of main thread.*/public static final String SYSTEM_SERVER_TIMING_TAG = "SystemServerTiming";/*** Tag for timing measurement of non-main asynchronous operations.*/private static final String SYSTEM_SERVER_TIMING_ASYNC_TAG = SYSTEM_SERVER_TIMING_TAG + "Async";/*** Set this to a positive value to get a {@Slog.w} log for any trace that took longer than it.*/private static final long BOTTLENECK_DURATION_MS = -1;private final String mTag;/*** Creates a new {@link TimingsTraceAndSlog} for async operations.*/@NonNullpublic static TimingsTraceAndSlog newAsyncLog() {return new TimingsTraceAndSlog(SYSTEM_SERVER_TIMING_ASYNC_TAG,Trace.TRACE_TAG_SYSTEM_SERVER);}/*** Default constructor using {@code system_server} tags.*/public TimingsTraceAndSlog() {this(SYSTEM_SERVER_TIMING_TAG);}/*** Custom constructor using {@code system_server} trace tag.** @param tag {@code logcat} tag*/public TimingsTraceAndSlog(@NonNull String tag) {this(tag, Trace.TRACE_TAG_SYSTEM_SERVER);}/*** Custom constructor.** @param tag {@code logcat} tag* @param traceTag {@code atrace} tag*/public TimingsTraceAndSlog(@NonNull String tag, long traceTag) {super(tag, traceTag);mTag = tag;}@Overridepublic void traceBegin(@NonNull String name) {// 使用Slog的Info级别输出Slog.i(mTag, name);// 调用父类TimingsTraceLog接口，输出Tracesuper.traceBegin(name);}@Overridepublic void logDuration(String name, long timeMs) {super.logDuration(name, timeMs);if (BOTTLENECK_DURATION_MS > 0 && timeMs >= BOTTLENECK_DURATION_MS) {Slog.w(mTag, "Slow duration for " + name + ": " + timeMs + "ms");}}@Overridepublic String toString() {return "TimingsTraceAndSlog[" + mTag + "]";}
}

父类TimingsTraceLog 中的相关实现。

/** Copyright (C) 2016 The Android Open Source Project** Licensed under the Apache License, Version 2.0 (the "License");* you may not use this file except in compliance with the License.* You may obtain a copy of the License at**      http://www.apache.org/licenses/LICENSE-2.0** Unless required by applicable law or agreed to in writing, software* distributed under the License is distributed on an "AS IS" BASIS,* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.* See the License for the specific language governing permissions and* limitations under the License.*/package android.util;import android.annotation.NonNull;
import android.os.Build;
import android.os.SystemClock;
import android.os.Trace;import com.android.internal.annotations.VisibleForTesting;import java.util.ArrayList;
import java.util.Collections;
import java.util.List;/*** Helper class for reporting boot and shutdown timing metrics.** <p><b>NOTE:</b> This class is not thread-safe. Use a separate copy for other threads.** @hide*/
public class TimingsTraceLog {// Debug boot time for every step if it's non-user build.// 注意：只有在非user编译下，才会输出每个阶段的耗时信息（耗时信息，也可以通过查看log日志的时间戳）private static final boolean DEBUG_BOOT_TIME = !Build.IS_USER;// Maximum number of nested calls that are storedprivate static final int MAX_NESTED_CALLS = 10;private final String[] mStartNames;private final long[] mStartTimes;private final String mTag;private final long mTraceTag;private final long mThreadId;private final int mMaxNestedCalls;private int mCurrentLevel = -1;public TimingsTraceLog(String tag, long traceTag) {this(tag, traceTag, DEBUG_BOOT_TIME ? MAX_NESTED_CALLS : -1);}@VisibleForTestingpublic TimingsTraceLog(String tag, long traceTag, int maxNestedCalls) {mTag = tag;mTraceTag = traceTag;mThreadId = Thread.currentThread().getId();mMaxNestedCalls = maxNestedCalls;if (maxNestedCalls > 0) {mStartNames = new String[maxNestedCalls];mStartTimes = new long[maxNestedCalls];} else {mStartNames = null;mStartTimes = null;}}/*** Begin tracing named section* @param name name to appear in trace*/public void traceBegin(String name) {assertSameThread();Trace.traceBegin(mTraceTag, name);if (!DEBUG_BOOT_TIME) return;if (mCurrentLevel + 1 >= mMaxNestedCalls) {Slog.w(mTag, "not tracing duration of '" + name + "' because already reached "+ mMaxNestedCalls + " levels");return;}mCurrentLevel++;mStartNames[mCurrentLevel] = name;mStartTimes[mCurrentLevel] = SystemClock.elapsedRealtime();}/*** End tracing previously {@link #traceBegin(String) started} section.** <p>Also {@link #logDuration logs} the duration.*/public void traceEnd() {assertSameThread();Trace.traceEnd(mTraceTag);if (!DEBUG_BOOT_TIME) return;if (mCurrentLevel < 0) {Slog.w(mTag, "traceEnd called more times than traceBegin");return;}final String name = mStartNames[mCurrentLevel];final long duration = SystemClock.elapsedRealtime() - mStartTimes[mCurrentLevel];mCurrentLevel--;logDuration(name, duration);}private void assertSameThread() {final Thread currentThread = Thread.currentThread();if (currentThread.getId() != mThreadId) {throw new IllegalStateException("Instance of TimingsTraceLog can only be called from "+ "the thread it was created on (tid: " + mThreadId + "), but was from "+ currentThread.getName() + " (tid: " + currentThread.getId() + ")");}}/*** Logs a duration so it can be parsed by external tools for performance reporting.*/public void logDuration(String name, long timeMs) {Slog.d(mTag, name + " took to complete: " + timeMs + "ms");}/*** Gets the names of the traces that {@link #traceBegin(String) have begun} but* {@link #traceEnd() have not finished} yet.** <p><b>NOTE:</b> this method is expensive and it should not be used in "production" - it* should only be used for debugging purposes during development (and/or guarded by* static {@code DEBUG} constants that are {@code false}).*/@NonNullpublic final List<String> getUnfinishedTracesForDebug() {if (mStartTimes == null || mCurrentLevel < 0) return Collections.emptyList();final ArrayList<String> list = new ArrayList<>(mCurrentLevel + 1);for (int i = 0; i <= mCurrentLevel; i++) {list.add(mStartNames[i]);}return list;}
}

SystemServer中输出SystemServerTiming日志。SystemServer会在其run函数中创建TimingsTraceAndSlog对象，然后调用这个对象的traceBegin和traceEnd函数。

// frameworks/base/services/java/com/android/server/SystemServer.javaprivate void run() {TimingsTraceAndSlog t = new TimingsTraceAndSlog();try {// 使用SystemServerTiming日志标签输出t.traceBegin("InitBeforeStartServices");// 省略....// Start services.try {t.traceBegin("StartServices");startBootstrapServices(t);startCoreServices(t);startOtherServices(t);} catch (Throwable ex) {Slog.e("System", "******************************************");Slog.e("System", "************ Failure starting system services", ex);throw ex;} finally {t.traceEnd(); // StartServices}// 省略... 
}