Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge "Log timings for shutdown stages" into oc-mr1-dev

Browse Source
This commit is contained in:
Fyodor Kupolov
2017-08-14 20:55:13 +00:00
committed by Android (Google) Code Review
parent 9b9d310a6d 6e3461b67c
commit fe97799d5d
11 changed files with 71 additions and 40 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
config/compiled-classes-phone
View File

@@ -4183,7 +4183,7 @@ android.util.Base64
android.util.Base64$Coder
android.util.Base64$Decoder
android.util.Base64$Encoder
android.util.BootTimingsTraceLog
android.util.TimingsTraceLog
android.util.ByteStringUtils
android.util.ContainerHelpers
android.util.DebugUtils

2
config/preloaded-classes
View File

@@ -2276,7 +2276,7 @@ android.util.Base64
android.util.Base64$Coder
android.util.Base64$Decoder
android.util.Base64$Encoder
android.util.BootTimingsTraceLog
android.util.TimingsTraceLog
android.util.ContainerHelpers
android.util.DisplayMetrics
android.util.EventLog

31
core/java/android/util/BootTimingsTraceLog.java → core/java/android/util/TimingsTraceLog.java
View File

@@ -11,7 +11,7 @@
* 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
* limitations under the License.
*/
package android.util;
@@ -24,22 +24,26 @@ import java.util.ArrayDeque;
import java.util.Deque;
/**
* Helper class for reporting boot timing metrics.
* Helper class for reporting boot and shutdown timing metrics.
* @hide
*/
public class BootTimingsTraceLog {
public class TimingsTraceLog {
// Debug boot time for every step if it's non-user build.
private static final boolean DEBUG_BOOT_TIME = !Build.IS_USER;
private final Deque<Pair<String, Long>> mStartTimes
= DEBUG_BOOT_TIME ? new ArrayDeque<>() : null;
private final Deque<Pair<String, Long>> mStartTimes =
DEBUG_BOOT_TIME ? new ArrayDeque<>() : null;
private final String mTag;
private long mTraceTag;
public BootTimingsTraceLog(String tag, long traceTag) {
public TimingsTraceLog(String tag, long traceTag) {
mTag = tag;
mTraceTag = traceTag;
}
/**
* Begin tracing named section
* @param name name to appear in trace
*/
public void traceBegin(String name) {
Trace.traceBegin(mTraceTag, name);
if (DEBUG_BOOT_TIME) {
@@ -47,6 +51,10 @@ public class BootTimingsTraceLog {
}
}
/**
* End tracing previously {@link #traceBegin(String) started} section.
* Also {@link #logDuration logs} the duration.
*/
public void traceEnd() {
Trace.traceEnd(mTraceTag);
if (!DEBUG_BOOT_TIME) {
@@ -57,8 +65,13 @@ public class BootTimingsTraceLog {
return;
}
Pair<String, Long> event = mStartTimes.pop();
// Log the duration so it can be parsed by external tools for performance reporting
Slog.d(mTag, event.first + " took to complete: "
+ (SystemClock.elapsedRealtime() - event.second) + "ms");
logDuration(event.first, (SystemClock.elapsedRealtime() - event.second));
}
/**
* Log the 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");
}
}

4
core/java/com/android/internal/os/WrapperInit.java
View File

@@ -23,7 +23,7 @@ import android.system.Os;
import android.system.OsConstants;
import android.system.StructCapUserData;
import android.system.StructCapUserHeader;
import android.util.BootTimingsTraceLog;
import android.util.TimingsTraceLog;
import android.util.Slog;
import dalvik.system.VMRuntime;
import java.io.DataOutputStream;
@@ -80,7 +80,7 @@ public class WrapperInit {
}
// Mimic system Zygote preloading.
ZygoteInit.preload(new BootTimingsTraceLog("WrapperInitTiming",
ZygoteInit.preload(new TimingsTraceLog("WrapperInitTiming",
Trace.TRACE_TAG_DALVIK));
// Launch the application.

9
core/java/com/android/internal/os/ZygoteInit.java
View File

@@ -43,7 +43,7 @@ import android.system.ErrnoException;
import android.system.Os;
import android.system.OsConstants;
import android.text.Hyphenator;
import android.util.BootTimingsTraceLog;
import android.util.TimingsTraceLog;
import android.util.EventLog;
import android.util.Log;
import android.util.Slog;
@@ -54,7 +54,6 @@ import com.android.internal.logging.MetricsLogger;
import com.android.internal.util.Preconditions;
import dalvik.system.DexFile;
import dalvik.system.PathClassLoader;
import dalvik.system.VMRuntime;
import dalvik.system.ZygoteHooks;
@@ -120,7 +119,7 @@ public class ZygoteInit {
private static boolean sPreloadComplete;
static void preload(BootTimingsTraceLog bootTimingsTraceLog) {
static void preload(TimingsTraceLog bootTimingsTraceLog) {
Log.d(TAG, "begin preload");
bootTimingsTraceLog.traceBegin("BeginIcuCachePinning");
beginIcuCachePinning();
@@ -153,7 +152,7 @@ public class ZygoteInit {
Preconditions.checkState(!sPreloadComplete);
Log.i(TAG, "Lazily preloading resources.");
preload(new BootTimingsTraceLog("ZygoteInitTiming_lazy", Trace.TRACE_TAG_DALVIK));
preload(new TimingsTraceLog("ZygoteInitTiming_lazy", Trace.TRACE_TAG_DALVIK));
}
private static void beginIcuCachePinning() {
@@ -719,7 +718,7 @@ public class ZygoteInit {
}
String bootTimeTag = Process.is64Bit() ? "Zygote64Timing" : "Zygote32Timing";
BootTimingsTraceLog bootTimingsTraceLog = new BootTimingsTraceLog(bootTimeTag,
TimingsTraceLog bootTimingsTraceLog = new TimingsTraceLog(bootTimeTag,
Trace.TRACE_TAG_DALVIK);
bootTimingsTraceLog.traceBegin("ZygoteInit");
RuntimeInit.enableDdms();

6
packages/SystemUI/src/com/android/systemui/SystemUIApplication.java
View File

@@ -30,10 +30,9 @@ import android.os.SystemProperties;
import android.os.Trace;
import android.os.UserHandle;
import android.util.ArraySet;
import android.util.BootTimingsTraceLog;
import android.util.TimingsTraceLog;
import android.util.Log;
import com.android.systemui.fragments.FragmentService;
import com.android.systemui.globalactions.GlobalActionsComponent;
import com.android.systemui.keyboard.KeyboardUI;
import com.android.systemui.keyguard.KeyguardViewMediator;
@@ -52,7 +51,6 @@ import com.android.systemui.stackdivider.Divider;
import com.android.systemui.statusbar.CommandQueue;
import com.android.systemui.statusbar.phone.StatusBar;
import com.android.systemui.statusbar.phone.StatusBarWindowManager;
import com.android.systemui.tuner.TunerService;
import com.android.systemui.usb.StorageNotification;
import com.android.systemui.util.NotificationChannels;
import com.android.systemui.util.leak.GarbageMonitor;
@@ -194,7 +192,7 @@ public class SystemUIApplication extends Application implements SysUiServiceProv
Log.v(TAG, "Starting SystemUI services for user " +
Process.myUserHandle().getIdentifier() + ".");
BootTimingsTraceLog log = new BootTimingsTraceLog("SystemUIBootTiming",
TimingsTraceLog log = new TimingsTraceLog("SystemUIBootTiming",
Trace.TRACE_TAG_APP);
log.traceBegin("StartServices");
final int N = services.length;

2
services/art-profile
View File

@@ -5445,7 +5445,7 @@ PLcom/android/server/am/ActivityManagerService;->stopAppSwitches()V
PLcom/android/server/am/ActivityManagerService;->stopAssociationLocked(ILjava/lang/String;ILandroid/content/ComponentName;)V
PLcom/android/server/am/ActivityManagerService;->stopService(Landroid/app/IApplicationThread;Landroid/content/Intent;Ljava/lang/String;I)I
PLcom/android/server/am/ActivityManagerService;->stopServiceToken(Landroid/content/ComponentName;Landroid/os/IBinder;I)Z
PLcom/android/server/am/ActivityManagerService;->systemReady(Ljava/lang/Runnable;Landroid/util/BootTimingsTraceLog;)V
PLcom/android/server/am/ActivityManagerService;->systemReady(Ljava/lang/Runnable;Landroid/util/TimingsTraceLog;)V
PLcom/android/server/am/ActivityManagerService;->trimApplications()V
PLcom/android/server/am/ActivityManagerService;->uidOnBackgroundWhitelist(I)Z
PLcom/android/server/am/ActivityManagerService;->unbindFinished(Landroid/os/IBinder;Landroid/content/Intent;Z)V

4
services/core/java/com/android/server/am/ActivityManagerService.java
View File

@@ -338,7 +338,7 @@ import android.text.style.SuggestionSpan;
import android.util.ArrayMap;
import android.util.ArraySet;
import android.util.AtomicFile;
import android.util.BootTimingsTraceLog;
import android.util.TimingsTraceLog;
import android.util.DebugUtils;
import android.util.DisplayMetrics;
import android.util.EventLog;
@@ -14049,7 +14049,7 @@ public class ActivityManagerService extends IActivityManager.Stub
}
}
public void systemReady(final Runnable goingCallback, BootTimingsTraceLog traceLog) {
public void systemReady(final Runnable goingCallback, TimingsTraceLog traceLog) {
traceLog.traceBegin("PhaseActivityManagerReady");
synchronized(this) {
if (mSystemReady) {

4
services/core/java/com/android/server/pm/PackageManagerService.java
View File

@@ -227,7 +227,7 @@ import android.text.format.DateUtils;
import android.util.ArrayMap;
import android.util.ArraySet;
import android.util.Base64;
import android.util.BootTimingsTraceLog;
import android.util.TimingsTraceLog;
import android.util.DisplayMetrics;
import android.util.EventLog;
import android.util.ExceptionUtils;
@@ -2940,7 +2940,7 @@ public class PackageManagerService extends IPackageManager.Stub
UserHandle.USER_SYSTEM, storageFlags, true /* migrateAppData */,
true /* onlyCoreApps */);
mPrepareAppDataFuture = SystemServerInitThreadPool.get().submit(() -> {
BootTimingsTraceLog traceLog = new BootTimingsTraceLog("SystemServerTimingAsync",
TimingsTraceLog traceLog = new TimingsTraceLog("SystemServerTimingAsync",
Trace.TRACE_TAG_PACKAGE_MANAGER);
traceLog.traceBegin("AppDataFixup");
try {

34
services/core/java/com/android/server/power/ShutdownThread.java
View File

@@ -45,16 +45,15 @@ import android.os.ServiceManager;
import android.os.SystemClock;
import android.os.SystemProperties;
import android.os.SystemVibrator;
import android.os.Trace;
import android.os.UserHandle;
import android.os.UserManager;
import android.os.Vibrator;
import android.os.storage.IStorageManager;
import android.os.storage.IStorageShutdownObserver;
import android.util.Log;
import android.view.ViewGroup;
import android.util.TimingsTraceLog;
import android.view.WindowManager;
import android.widget.ProgressBar;
import android.widget.TextView;
import com.android.internal.telephony.ITelephony;
import com.android.server.RescueParty;
@@ -108,6 +107,9 @@ public final class ShutdownThread extends Thread {
.setUsage(AudioAttributes.USAGE_ASSISTANCE_SONIFICATION)
.build();
private static final TimingsTraceLog SHUTDOWN_TIMINGS_LOG = new TimingsTraceLog(
"ShutdownTiming", Trace.TRACE_TAG_SYSTEM_SERVER);
private final Object mActionDoneSync = new Object();
private boolean mActionDone;
private Context mContext;
@@ -346,6 +348,7 @@ public final class ShutdownThread extends Thread {
}
private static void beginShutdownSequence(Context context) {
SHUTDOWN_TIMINGS_LOG.traceBegin("SystemServerShutdown");
synchronized (sIsStartedGuard) {
if (sIsStarted) {
Log.d(TAG, "Shutdown sequence already running, returning.");
@@ -427,6 +430,7 @@ public final class ShutdownThread extends Thread {
SystemProperties.set(REBOOT_SAFEMODE_PROPERTY, "1");
}
SHUTDOWN_TIMINGS_LOG.traceBegin("SendShutdownBroadcast");
Log.i(TAG, "Sending shutdown broadcast...");
// First send the high-level shut down broadcast.
@@ -458,8 +462,10 @@ public final class ShutdownThread extends Thread {
if (mRebootHasProgressBar) {
sInstance.setRebootProgress(BROADCAST_STOP_PERCENT, null);
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // SendShutdownBroadcast
Log.i(TAG, "Shutting down activity manager...");
SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownActivityManager");
final IActivityManager am =
IActivityManager.Stub.asInterface(ServiceManager.checkService("activity"));
@@ -472,8 +478,10 @@ public final class ShutdownThread extends Thread {
if (mRebootHasProgressBar) {
sInstance.setRebootProgress(ACTIVITY_MANAGER_STOP_PERCENT, null);
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownActivityManager
Log.i(TAG, "Shutting down package manager...");
SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownPackageManager");
final PackageManagerService pm = (PackageManagerService)
ServiceManager.getService("package");
@@ -483,12 +491,15 @@ public final class ShutdownThread extends Thread {
if (mRebootHasProgressBar) {
sInstance.setRebootProgress(PACKAGE_MANAGER_STOP_PERCENT, null);
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownPackageManager
// Shutdown radios.
SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownRadios");
shutdownRadios(MAX_RADIO_WAIT_TIME);
if (mRebootHasProgressBar) {
sInstance.setRebootProgress(RADIO_STOP_PERCENT, null);
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownRadios
// Shutdown StorageManagerService to ensure media is in a safe state
IStorageShutdownObserver observer = new IStorageShutdownObserver.Stub() {
@@ -499,6 +510,7 @@ public final class ShutdownThread extends Thread {
};
Log.i(TAG, "Shutting down StorageManagerService");
SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownStorageManager");
// Set initial variables and time out time.
mActionDone = false;
@@ -518,7 +530,7 @@ public final class ShutdownThread extends Thread {
while (!mActionDone) {
long delay = endShutTime - SystemClock.elapsedRealtime();
if (delay <= 0) {
Log.w(TAG, "Shutdown wait timed out");
Log.w(TAG, "StorageManager shutdown wait timed out");
break;
} else if (mRebootHasProgressBar) {
int status = (int)((MAX_SHUTDOWN_WAIT_TIME - delay) * 1.0 *
@@ -533,6 +545,8 @@ public final class ShutdownThread extends Thread {
}
}
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownStorageManager
if (mRebootHasProgressBar) {
sInstance.setRebootProgress(MOUNT_SERVICE_STOP_PERCENT, null);
@@ -576,7 +590,7 @@ public final class ShutdownThread extends Thread {
final IBluetoothManager bluetooth =
IBluetoothManager.Stub.asInterface(ServiceManager.checkService(
BluetoothAdapter.BLUETOOTH_MANAGER_SERVICE));
final long nfcShutdownStarted = SystemClock.elapsedRealtime();
try {
nfcOff = nfc == null ||
nfc.getState() == NfcAdapter.STATE_OFF;
@@ -589,6 +603,7 @@ public final class ShutdownThread extends Thread {
nfcOff = true;
}
final long btShutdownStarted = SystemClock.elapsedRealtime();
try {
bluetoothReadyForShutdown = bluetooth == null ||
bluetooth.getState() == BluetoothAdapter.STATE_OFF;
@@ -601,6 +616,7 @@ public final class ShutdownThread extends Thread {
bluetoothReadyForShutdown = true;
}
final long radioShutdownStarted = SystemClock.elapsedRealtime();
try {
radioOff = phone == null || !phone.needMobileRadioShutdown();
if (!radioOff) {
@@ -637,6 +653,8 @@ public final class ShutdownThread extends Thread {
}
if (bluetoothReadyForShutdown) {
Log.i(TAG, "Bluetooth turned off.");
SHUTDOWN_TIMINGS_LOG.logDuration("ShutdownBt",
SystemClock.elapsedRealtime() - btShutdownStarted);
}
}
if (!radioOff) {
@@ -648,6 +666,8 @@ public final class ShutdownThread extends Thread {
}
if (radioOff) {
Log.i(TAG, "Radio turned off.");
SHUTDOWN_TIMINGS_LOG.logDuration("ShutdownRadio",
SystemClock.elapsedRealtime() - radioShutdownStarted);
}
}
if (!nfcOff) {
@@ -659,6 +679,8 @@ public final class ShutdownThread extends Thread {
}
if (nfcOff) {
Log.i(TAG, "NFC turned off.");
SHUTDOWN_TIMINGS_LOG.logDuration("ShutdownNfc",
SystemClock.elapsedRealtime() - nfcShutdownStarted);
}
}
@@ -714,7 +736,7 @@ public final class ShutdownThread extends Thread {
} catch (InterruptedException unused) {
}
}
SHUTDOWN_TIMINGS_LOG.traceEnd(); // SystemServerShutdown
// Shutdown power
Log.i(TAG, "Performing low-level shutdown...");
PowerManagerService.lowLevelShutdown(reason);

13
services/java/com/android/server/SystemServer.java
View File

@@ -45,7 +45,7 @@ import android.os.SystemProperties;
import android.os.Trace;
import android.os.UserHandle;
import android.os.storage.IStorageManager;
import android.util.BootTimingsTraceLog;
import android.util.TimingsTraceLog;
import android.util.DisplayMetrics;
import android.util.EventLog;
import android.util.Slog;
@@ -121,7 +121,6 @@ import java.io.File;
import java.io.IOException;
import java.util.Locale;
import java.util.Timer;
import java.util.TimerTask;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.Future;
@@ -135,8 +134,8 @@ public final class SystemServer {
// Tag for timing measurement of non-main asynchronous operations.
private static final String SYSTEM_SERVER_TIMING_ASYNC_TAG = SYSTEM_SERVER_TIMING_TAG + "Async";
private static final BootTimingsTraceLog BOOT_TIMINGS_TRACE_LOG
= new BootTimingsTraceLog(SYSTEM_SERVER_TIMING_TAG, Trace.TRACE_TAG_SYSTEM_SERVER);
private static final TimingsTraceLog BOOT_TIMINGS_TRACE_LOG
= new TimingsTraceLog(SYSTEM_SERVER_TIMING_TAG, Trace.TRACE_TAG_SYSTEM_SERVER);
private static final String ENCRYPTING_STATE = "trigger_restart_min_framework";
private static final String ENCRYPTED_STATE = "1";
@@ -638,7 +637,7 @@ public final class SystemServer {
// Start sensor service in a separate thread. Completion should be checked
// before using it.
mSensorServiceStart = SystemServerInitThreadPool.get().submit(() -> {
BootTimingsTraceLog traceLog = new BootTimingsTraceLog(
TimingsTraceLog traceLog = new TimingsTraceLog(
SYSTEM_SERVER_TIMING_ASYNC_TAG, Trace.TRACE_TAG_SYSTEM_SERVER);
traceLog.traceBegin(START_SENSOR_SERVICE);
startSensorService();
@@ -736,7 +735,7 @@ public final class SystemServer {
mZygotePreload = SystemServerInitThreadPool.get().submit(() -> {
try {
Slog.i(TAG, SECONDARY_ZYGOTE_PRELOAD);
BootTimingsTraceLog traceLog = new BootTimingsTraceLog(
TimingsTraceLog traceLog = new TimingsTraceLog(
SYSTEM_SERVER_TIMING_ASYNC_TAG, Trace.TRACE_TAG_SYSTEM_SERVER);
traceLog.traceBegin(SECONDARY_ZYGOTE_PRELOAD);
if (!Process.zygoteProcess.preloadDefault(Build.SUPPORTED_32_BIT_ABIS[0])) {
@@ -1686,7 +1685,7 @@ public final class SystemServer {
if (!mOnlyCore) {
webviewPrep = SystemServerInitThreadPool.get().submit(() -> {
Slog.i(TAG, WEBVIEW_PREPARATION);
BootTimingsTraceLog traceLog = new BootTimingsTraceLog(
TimingsTraceLog traceLog = new TimingsTraceLog(
SYSTEM_SERVER_TIMING_ASYNC_TAG, Trace.TRACE_TAG_SYSTEM_SERVER);
traceLog.traceBegin(WEBVIEW_PREPARATION);
ConcurrentUtils.waitForFutureNoInterrupt(mZygotePreload, "Zygote preload");