commit b11675a9ce679190f7641672b5ea8a24b67446af
author Hall Liu <hallliu@google.com> Mon Aug 26 18:14:34 2019 -0700
committer Hall Liu <hallliu@google.com> Mon Aug 26 18:16:29 2019 -0700
tree 009f4137b17fda029e42662735ecd3ed9f56e563
parent 6fef702dd07f4832d3994480e017e86379633468

Add timing logging for startRinging

Multiple bug reports have indicated a delay in the methods that
constitute the starting portion of Ringer#startRinging. Adding some
speculative logging to catch which method call is the slow one.

Bug: 137437748
Test: manual
Change-Id: I1f8a0eacfd93be73fd93b58dd5b6aec76d447877

src/com/android/server/telecom/LogUtils.java

diff --git a/src/com/android/server/telecom/LogUtils.java b/src/com/android/server/telecom/LogUtils.java
index 760d24e..1e82fc0 100644
--- a/src/com/android/server/telecom/LogUtils.java
+++ b/src/com/android/server/telecom/LogUtils.java
@@ -17,9 +17,13 @@
 package com.android.server.telecom;
 
 import android.content.Context;
+import android.os.SystemClock;
 import android.telecom.Logging.EventManager;
 import android.telecom.Logging.EventManager.TimedEventPair;
 
+import java.util.HashMap;
+import java.util.Map;
+
 /**
  * Temporary location of new Logging class
  */
@@ -31,6 +35,30 @@
 
     public static final boolean SYSTRACE_DEBUG = false; /* STOP SHIP if true */
 
+    public static class EventTimer {
+        private long mLastElapsedMillis;
+        private Map<String, Long> mTimings = new HashMap<>();
+
+        public EventTimer() {
+            mLastElapsedMillis = SystemClock.elapsedRealtime();
+        }
+
+        public void record(String label) {
+            long newElapsedMillis = SystemClock.elapsedRealtime();
+            mTimings.put(label, newElapsedMillis - mLastElapsedMillis);
+            mLastElapsedMillis = newElapsedMillis;
+        }
+
+        @Override
+        public String toString() {
+            StringBuilder sb = new StringBuilder();
+            for (Map.Entry<String, Long> entry : mTimings.entrySet()) {
+                sb.append(entry.getKey()).append(": ").append(entry.getValue()).append(", ");
+            }
+            return sb.toString();
+        }
+    }
+
     public static final class Sessions {
         public static final String ICA_ANSWER_CALL = "ICA.aC";
         public static final String ICA_DEFLECT_CALL = "ICA.defC";

src/com/android/server/telecom/Ringer.java

diff --git a/src/com/android/server/telecom/Ringer.java b/src/com/android/server/telecom/Ringer.java
index f1e669a..6ce5d9f 100644
--- a/src/com/android/server/telecom/Ringer.java
+++ b/src/com/android/server/telecom/Ringer.java
@@ -31,6 +31,7 @@
 import android.os.Vibrator;
 
 import com.android.internal.annotations.VisibleForTesting;
+import com.android.server.telecom.LogUtils.EventTimer;
 
 import java.util.ArrayList;
 
@@ -156,14 +157,32 @@
 
         AudioManager audioManager =
                 (AudioManager) mContext.getSystemService(Context.AUDIO_SERVICE);
+        LogUtils.EventTimer timer = new EventTimer();
         boolean isVolumeOverZero = audioManager.getStreamVolume(AudioManager.STREAM_RING) > 0;
+        timer.record("isVolumeOverZero");
         boolean shouldRingForContact = shouldRingForContact(foregroundCall.getContactUri());
+        timer.record("shouldRingForContact");
         boolean isRingtonePresent = !(mRingtoneFactory.getRingtone(foregroundCall) == null);
+        timer.record("getRingtone");
         boolean isSelfManaged = foregroundCall.isSelfManaged();
+        timer.record("isSelfManaged");
         boolean isSilentRingingRequested = foregroundCall.isSilentRingingRequested();
+        timer.record("isSilentRingRequested");
 
         boolean isRingerAudible = isVolumeOverZero && shouldRingForContact && isRingtonePresent;
+        timer.record("isRingerAudible");
         boolean hasExternalRinger = hasExternalRinger(foregroundCall);
+        timer.record("hasExternalRinger");
+        // Don't do call waiting operations or vibration unless these are false.
+        boolean isTheaterModeOn = mSystemSettingsUtil.isTheaterModeOn(mContext);
+        timer.record("isTheaterModeOn");
+        boolean letDialerHandleRinging = mInCallController.doesConnectedDialerSupportRinging();
+        timer.record("letDialerHandleRinging");
+
+        Log.i(this, "startRinging timings: " + timer);
+        boolean endEarly = isTheaterModeOn || letDialerHandleRinging || isSelfManaged ||
+                hasExternalRinger || isSilentRingingRequested;
+
         // Acquire audio focus under any of the following conditions:
         // 1. Should ring for contact and there's an HFP device attached
         // 2. Volume is over zero, we should ring for the contact, and there's a audible ringtone
@@ -172,12 +191,6 @@
         boolean shouldAcquireAudioFocus =
                 isRingerAudible || (isHfpDeviceAttached && shouldRingForContact) || isSelfManaged;
 
-        // Don't do call waiting operations or vibration unless these are false.
-        boolean isTheaterModeOn = mSystemSettingsUtil.isTheaterModeOn(mContext);
-        boolean letDialerHandleRinging = mInCallController.doesConnectedDialerSupportRinging();
-        boolean endEarly = isTheaterModeOn || letDialerHandleRinging || isSelfManaged ||
-                hasExternalRinger || isSilentRingingRequested;
-
         if (endEarly) {
             if (letDialerHandleRinging) {
                 Log.addEvent(foregroundCall, LogUtils.Events.SKIP_RINGING, "Dialer handles");