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

Log the duration of executing all receivers of LOCKED_BOOT_COMPLETED or BOOT_COMPLETED broadcast.

Browse Source 
The dispatch latency is the dispatchTime - enqueueTime.
The completion latency is the completionTime - enqueueTime.

Bug: 221320741
Test: after reboot and unlock device, grep BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED in adb logcat ouput.
Change-Id: If2d91c9cea30228518ff7a5229de2dcbee28c9cc
Merged-In: If2d91c9cea30228518ff7a5229de2dcbee28c9cc
This commit is contained in:
Hui Yu
2022-02-28 10:16:16 -08:00
parent f4ca38973f
commit 66b902f8a7
2 changed files with 81 additions and 4 deletions
Download Patch File Download Diff File Expand all files Collapse all files

67
services/core/java/com/android/server/am/BroadcastQueue.java
View File

@@ -21,6 +21,9 @@ import static android.os.Process.ZYGOTE_POLICY_FLAG_EMPTY;
import static android.os.Process.ZYGOTE_POLICY_FLAG_LATENCY_SENSITIVE;
import static android.text.TextUtils.formatSimple;
import static com.android.internal.util.FrameworkStatsLog.BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED;
import static com.android.internal.util.FrameworkStatsLog.BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED__EVENT__BOOT_COMPLETED;
import static com.android.internal.util.FrameworkStatsLog.BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED__EVENT__LOCKED_BOOT_COMPLETED;
import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BROADCAST;
import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BROADCAST_DEFERRAL;
import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BROADCAST_LIGHT;
@@ -29,6 +32,7 @@ import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_PERMISSIONS
import static com.android.server.am.ActivityManagerDebugConfig.POSTFIX_BROADCAST;
import static com.android.server.am.ActivityManagerDebugConfig.POSTFIX_MU;
import android.annotation.NonNull;
import android.annotation.Nullable;
import android.app.ActivityManager;
@@ -51,6 +55,7 @@ import android.content.pm.ApplicationInfo;
import android.content.pm.PackageManager;
import android.content.pm.PermissionInfo;
import android.content.pm.ResolveInfo;
import android.content.pm.UserInfo;
import android.os.Bundle;
import android.os.Handler;
import android.os.IBinder;
@@ -64,6 +69,7 @@ import android.os.RemoteException;
import android.os.SystemClock;
import android.os.Trace;
import android.os.UserHandle;
import android.os.UserManager;
import android.permission.IPermissionManager;
import android.text.TextUtils;
import android.util.EventLog;
@@ -75,6 +81,7 @@ import android.util.proto.ProtoOutputStream;
import com.android.internal.util.ArrayUtils;
import com.android.internal.util.FrameworkStatsLog;
import com.android.server.LocalServices;
import com.android.server.pm.UserManagerInternal;
import java.io.FileDescriptor;
import java.io.PrintWriter;
@@ -250,12 +257,16 @@ public final class BroadcastQueue {
public void enqueueParallelBroadcastLocked(BroadcastRecord r) {
r.enqueueClockTime = System.currentTimeMillis();
r.enqueueTime = SystemClock.uptimeMillis();
r.enqueueRealTime = SystemClock.elapsedRealtime();
mParallelBroadcasts.add(r);
enqueueBroadcastHelper(r);
}
public void enqueueOrderedBroadcastLocked(BroadcastRecord r) {
r.enqueueClockTime = System.currentTimeMillis();
r.enqueueTime = SystemClock.uptimeMillis();
r.enqueueRealTime = SystemClock.elapsedRealtime();
mDispatcher.enqueueOrderedBroadcastLocked(r);
enqueueBroadcastHelper(r);
}
@@ -1121,6 +1132,7 @@ public final class BroadcastQueue {
while (mParallelBroadcasts.size() > 0) {
r = mParallelBroadcasts.remove(0);
r.dispatchTime = SystemClock.uptimeMillis();
r.dispatchRealTime = SystemClock.elapsedRealtime();
r.dispatchClockTime = System.currentTimeMillis();
if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
@@ -1292,6 +1304,7 @@ public final class BroadcastQueue {
performReceiveLocked(r.callerApp, r.resultTo,
new Intent(r.intent), r.resultCode,
r.resultData, r.resultExtras, false, false, r.userId);
logBootCompletedBroadcastCompletionLatencyIfPossible(r);
// Set this to null so that the reference
// (local and remote) isn't kept in the mBroadcastHistory.
r.resultTo = null;
@@ -1408,6 +1421,7 @@ public final class BroadcastQueue {
r.receiverTime = SystemClock.uptimeMillis();
if (recIdx == 0) {
r.dispatchTime = r.receiverTime;
r.dispatchRealTime = SystemClock.elapsedRealtime();
r.dispatchClockTime = System.currentTimeMillis();
if (mLogLatencyMetrics) {
@@ -1866,6 +1880,59 @@ public final class BroadcastQueue {
return null;
}
private void logBootCompletedBroadcastCompletionLatencyIfPossible(BroadcastRecord r) {
// Only log after last receiver.
// In case of split BOOT_COMPLETED broadcast, make sure only call this method on the
// last BroadcastRecord of the split broadcast which has non-null resultTo.
final int numReceivers = (r.receivers != null) ? r.receivers.size() : 0;
if (r.nextReceiver < numReceivers) {
return;
}
final String action = r.intent.getAction();
int event = 0;
if (Intent.ACTION_LOCKED_BOOT_COMPLETED.equals(action)) {
event = BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED__EVENT__LOCKED_BOOT_COMPLETED;
} else if (Intent.ACTION_BOOT_COMPLETED.equals(action)) {
event = BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED__EVENT__BOOT_COMPLETED;
}
if (event != 0) {
final int dispatchLatency = (int)(r.dispatchTime - r.enqueueTime);
final int completeLatency = (int)
(SystemClock.uptimeMillis() - r.enqueueTime);
final int dispatchRealLatency = (int)(r.dispatchRealTime - r.enqueueRealTime);
final int completeRealLatency = (int)
(SystemClock.elapsedRealtime() - r.enqueueRealTime);
int userType = FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED__USER_TYPE__TYPE_UNKNOWN;
// This method is called very infrequently, no performance issue we call
// LocalServices.getService() here.
final UserManagerInternal umInternal = LocalServices.getService(
UserManagerInternal.class);
final UserInfo userInfo = umInternal.getUserInfo(r.userId);
if (userInfo != null) {
userType = UserManager.getUserTypeForStatsd(userInfo.userType);
}
Slog.i(TAG_BROADCAST,
"BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED action:"
+ action
+ " dispatchLatency:" + dispatchLatency
+ " completeLatency:" + completeLatency
+ " dispatchRealLatency:" + dispatchRealLatency
+ " completeRealLatency:" + completeRealLatency
+ " receiversSize:" + r.receivers.size()
+ " userId:" + r.userId
+ " userType:" + (userInfo != null? userInfo.userType : null));
FrameworkStatsLog.write(
BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED,
event,
dispatchLatency,
completeLatency,
dispatchRealLatency,
completeRealLatency,
r.userId,
userType);
}
}
private void maybeReportBroadcastDispatchedEventLocked(BroadcastRecord r, int targetUid) {
// STOPSHIP (217251579): Temporarily use temp-allowlist reason to identify
// push messages and record response events.

18
services/core/java/com/android/server/am/BroadcastRecord.java
View File

@@ -84,11 +84,14 @@ final class BroadcastRecord extends Binder {
boolean deferred;
int splitCount; // refcount for result callback, when split
int splitToken; // identifier for cross-BroadcastRecord refcount
long enqueueTime; // uptimeMillis when the broadcast was enqueued
long enqueueRealTime; // elapsedRealtime when the broadcast was enqueued
long enqueueClockTime; // the clock time the broadcast was enqueued
long dispatchTime; // when dispatch started on this set of receivers
long dispatchRealTime; // elapsedRealtime when the broadcast was dispatched
long dispatchClockTime; // the clock time the dispatch started
long receiverTime; // when current receiver started for timeouts.
long finishTime; // when we finished the broadcast.
long finishTime; // when we finished the current receiver.
boolean timeoutExempt; // true if this broadcast is not subject to receiver timeouts
int resultCode; // current result code value.
String resultData; // current result data value.
@@ -169,7 +172,7 @@ final class BroadcastRecord extends Binder {
pw.print(prefix); pw.print("dispatchTime=");
TimeUtils.formatDuration(dispatchTime, now, pw);
pw.print(" (");
TimeUtils.formatDuration(dispatchClockTime-enqueueClockTime, pw);
TimeUtils.formatDuration(dispatchTime - enqueueTime, pw);
pw.print(" since enq)");
if (finishTime != 0) {
pw.print(" finishTime="); TimeUtils.formatDuration(finishTime, now, pw);
@@ -324,8 +327,11 @@ final class BroadcastRecord extends Binder {
delivery = from.delivery;
duration = from.duration;
resultTo = from.resultTo;
enqueueTime = from.enqueueTime;
enqueueRealTime = from.enqueueRealTime;
enqueueClockTime = from.enqueueClockTime;
dispatchTime = from.dispatchTime;
dispatchRealTime = from.dispatchRealTime;
dispatchClockTime = from.dispatchClockTime;
receiverTime = from.receiverTime;
finishTime = from.finishTime;
@@ -378,7 +384,9 @@ final class BroadcastRecord extends Binder {
requiredPermissions, excludedPermissions, appOp, options, splitReceivers, resultTo,
resultCode, resultData, resultExtras, ordered, sticky, initialSticky, userId,
allowBackgroundActivityStarts, mBackgroundActivityStartsToken, timeoutExempt);
split.enqueueTime = this.enqueueTime;
split.enqueueRealTime = this.enqueueRealTime;
split.enqueueClockTime = this.enqueueClockTime;
split.splitToken = this.splitToken;
return split;
}
@@ -448,9 +456,11 @@ final class BroadcastRecord extends Binder {
final BroadcastRecord br = new BroadcastRecord(queue, intent, callerApp, callerPackage,
callerFeatureId, callingPid, callingUid, callerInstantApp, resolvedType,
requiredPermissions, excludedPermissions, appOp, options,
uid2receiverList.valueAt(i), resultTo,
uid2receiverList.valueAt(i), null /* _resultTo */,
resultCode, resultData, resultExtras, ordered, sticky, initialSticky, userId,
allowBackgroundActivityStarts, mBackgroundActivityStartsToken, timeoutExempt);
br.enqueueTime = this.enqueueTime;
br.enqueueRealTime = this.enqueueRealTime;
br.enqueueClockTime = this.enqueueClockTime;
ret.put(uid2receiverList.keyAt(i), br);
}