Merge "Add support for new SessionManager and EventManager tests" (42598f4a) · Commits · e / os / android_frameworks_base

telecomm/java/android/telecom/Logging/EventManager.java

+13 −1

Original line number	Diff line number	Diff line
		@@ -20,6 +20,7 @@ import android.annotation.NonNull;
		import android.telecom.Log;
		import android.text.TextUtils;

		import com.android.internal.annotations.VisibleForTesting;
		import com.android.internal.util.IndentingPrintWriter;

		import java.text.DateFormat;
		@@ -46,6 +47,7 @@ import java.util.concurrent.LinkedBlockingQueue;
		public class EventManager {

		public static final String TAG = "Logging.Events";
		@VisibleForTesting
		public static final int DEFAULT_EVENTS_TO_CACHE = 10; // Arbitrarily chosen.

		public interface Loggable {
		@@ -79,7 +81,7 @@ public class EventManager {
		* Maps from request events to a list of possible response events. Used to track
		* end-to-end timing for critical user-facing operations in Telecom.
		*/
		public final Map<String, List<TimedEventPair>> requestResponsePairs = new HashMap<>();
		private final Map<String, List<TimedEventPair>> requestResponsePairs = new HashMap<>();

		private static final Object mSync = new Object();

		@@ -340,6 +342,16 @@ public class EventManager {
		}
		}

		@VisibleForTesting
		public LinkedBlockingQueue<EventRecord> getEventRecords() {
		return mEventRecords;
		}

		@VisibleForTesting
		public Map<Loggable, EventRecord> getCallEventRecordMap() {
		return mCallEventRecordMap;
		}

		private void addEventRecord(EventRecord newRecord) {
		Loggable recordEntry = newRecord.getRecordEntry();

telecomm/java/android/telecom/Logging/Session.java

+48 −21

Original line number	Diff line number	Diff line
		@@ -33,6 +33,10 @@ public class Session {
		public static final String END_SUBSESSION = "END_SUBSESSION";
		public static final String END_SESSION = "END_SESSION";

		/**
		* Initial value of mExecutionEndTimeMs and the final value of {@link #getLocalExecutionTime()}
		* if the Session is canceled.
		*/
		public static final int UNDEFINED = -1;

		private String mSessionId;
		@@ -140,27 +144,6 @@ public class Session {
		return String.valueOf(mChildCounter++);
		}

		@Override
		public boolean equals(Object obj) {
		if (!(obj instanceof Session)) {
		return false;
		}
		if (obj == this) {
		return true;
		}
		Session otherSession = (Session) obj;
		return (mSessionId.equals(otherSession.mSessionId)) &&
		(mShortMethodName.equals(otherSession.mShortMethodName)) &&
		mExecutionStartTimeMs == otherSession.mExecutionStartTimeMs &&
		mParentSession == otherSession.mParentSession &&
		mChildSessions.equals(otherSession.mChildSessions) &&
		mIsCompleted == otherSession.mIsCompleted &&
		mExecutionEndTimeMs == otherSession.mExecutionEndTimeMs &&
		mChildCounter == otherSession.mChildCounter &&
		mIsStartedFromActiveSession == otherSession.mIsStartedFromActiveSession &&
		mOwnerInfo == otherSession.mOwnerInfo;
		}

		// Builds full session id recursively
		private String getFullSessionId() {
		// Cache mParentSession locally to prevent a concurrency problem where
		@@ -203,6 +186,50 @@ public class Session {
		}
		}

		@Override
		public int hashCode() {
		int result = mSessionId != null ? mSessionId.hashCode() : 0;
		result = 31 * result + (mShortMethodName != null ? mShortMethodName.hashCode() : 0);
		result = 31 * result + (int) (mExecutionStartTimeMs ^ (mExecutionStartTimeMs >>> 32));
		result = 31 * result + (int) (mExecutionEndTimeMs ^ (mExecutionEndTimeMs >>> 32));
		result = 31 * result + (mParentSession != null ? mParentSession.hashCode() : 0);
		result = 31 * result + (mChildSessions != null ? mChildSessions.hashCode() : 0);
		result = 31 * result + (mIsCompleted ? 1 : 0);
		result = 31 * result + mChildCounter;
		result = 31 * result + (mIsStartedFromActiveSession ? 1 : 0);
		result = 31 * result + (mOwnerInfo != null ? mOwnerInfo.hashCode() : 0);
		return result;
		}

		@Override
		public boolean equals(Object o) {
		if (this == o) return true;
		if (o == null \|\| getClass() != o.getClass()) return false;

		Session session = (Session) o;

		if (mExecutionStartTimeMs != session.mExecutionStartTimeMs) return false;
		if (mExecutionEndTimeMs != session.mExecutionEndTimeMs) return false;
		if (mIsCompleted != session.mIsCompleted) return false;
		if (mChildCounter != session.mChildCounter) return false;
		if (mIsStartedFromActiveSession != session.mIsStartedFromActiveSession) return false;
		if (mSessionId != null ?
		!mSessionId.equals(session.mSessionId) : session.mSessionId != null)
		return false;
		if (mShortMethodName != null ? !mShortMethodName.equals(session.mShortMethodName)
		: session.mShortMethodName != null)
		return false;
		if (mParentSession != null ? !mParentSession.equals(session.mParentSession)
		: session.mParentSession != null)
		return false;
		if (mChildSessions != null ? !mChildSessions.equals(session.mChildSessions)
		: session.mChildSessions != null)
		return false;
		return mOwnerInfo != null ? mOwnerInfo.equals(session.mOwnerInfo)
		: session.mOwnerInfo == null;

		}

		@Override
		public String toString() {
		if (mParentSession != null && mIsStartedFromActiveSession) {

telecomm/java/android/telecom/Logging/SessionManager.java

+43 −34

Original line number	Diff line number	Diff line
		@@ -19,6 +19,7 @@ package android.telecom.Logging;
		import android.content.Context;
		import android.os.Handler;
		import android.os.Looper;
		import android.os.Process;
		import android.provider.Settings;
		import android.util.Base64;

		@@ -53,11 +54,11 @@ public class SessionManager {
		private Context mContext;

		@VisibleForTesting
		public ConcurrentHashMap<Integer, Session> sSessionMapper = new ConcurrentHashMap<>(100);
		public ConcurrentHashMap<Integer, Session> mSessionMapper = new ConcurrentHashMap<>(100);
		@VisibleForTesting
		public Handler sSessionCleanupHandler = new Handler(Looper.getMainLooper());
		public Handler mSessionCleanupHandler = new Handler(Looper.getMainLooper());
		@VisibleForTesting
		public java.lang.Runnable sCleanStaleSessions = () ->
		public java.lang.Runnable mCleanStaleSessions = () ->
		cleanupStaleSessions(getSessionCleanupTimeoutMs());

		// Overridden in LogTest to skip query to ContentProvider
		@@ -65,8 +66,16 @@ public class SessionManager {
		long get();
		}

		// Overridden in tests to provide test Thread IDs
		public interface ICurrentThreadId {
		int get();
		}

		@VisibleForTesting
		public ICurrentThreadId mCurrentThreadId = Process::myTid;

		@VisibleForTesting
		public ISessionCleanupTimeoutMs sSessionCleanupTimeoutMs = () -> {
		public ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> {
		// mContext may be null in some cases, such as testing. For these cases, use the
		// default value.
		if (mContext == null) {
		@@ -99,14 +108,14 @@ public class SessionManager {
		}

		private long getSessionCleanupTimeoutMs() {
		return sSessionCleanupTimeoutMs.get();
		return mSessionCleanupTimeoutMs.get();
		}

		private synchronized void resetStaleSessionTimer() {
		sSessionCleanupHandler.removeCallbacksAndMessages(null);
		mSessionCleanupHandler.removeCallbacksAndMessages(null);
		// Will be null in Log Testing
		if (sCleanStaleSessions != null) {
		sSessionCleanupHandler.postDelayed(sCleanStaleSessions, getSessionCleanupTimeoutMs());
		if (mCleanStaleSessions != null) {
		mSessionCleanupHandler.postDelayed(mCleanStaleSessions, getSessionCleanupTimeoutMs());
		}
		}

		@@ -118,7 +127,7 @@ public class SessionManager {
		String callerIdentification) {
		resetStaleSessionTimer();
		int threadId = getCallingThreadId();
		Session activeSession = sSessionMapper.get(threadId);
		Session activeSession = mSessionMapper.get(threadId);
		// We have called startSession within an active session that has not ended... Register this
		// session as a subsession.
		if (activeSession != null) {
		@@ -128,9 +137,9 @@ public class SessionManager {
		}
		Session newSession = new Session(getNextSessionID(), shortMethodName,
		System.currentTimeMillis(), threadId, false, callerIdentification);
		sSessionMapper.put(threadId, newSession);
		mSessionMapper.put(threadId, newSession);

		android.telecom.Log.v(LOGGING_TAG, Session.START_SESSION);
		android.util.Slog.v(LOGGING_TAG, Session.START_SESSION);
		}


		@@ -145,9 +154,9 @@ public class SessionManager {

		private synchronized Session createSubsession(boolean isStartedFromActiveSession) {
		int threadId = getCallingThreadId();
		Session threadSession = sSessionMapper.get(threadId);
		Session threadSession = mSessionMapper.get(threadId);
		if (threadSession == null) {
		android.telecom.Log.d(LOGGING_TAG, "Log.createSubsession was called with no session " +
		android.util.Slog.d(LOGGING_TAG, "Log.createSubsession was called with no session " +
		"active.");
		return null;
		}
		@@ -159,10 +168,10 @@ public class SessionManager {
		newSubsession.setParentSession(threadSession);

		if (!isStartedFromActiveSession) {
		android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
		android.util.Slog.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
		newSubsession.toString());
		} else {
		android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
		android.util.Slog.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
		" (Invisible subsession)");
		}
		return newSubsession;
		@@ -171,14 +180,14 @@ public class SessionManager {
		/**
		* Cancels a subsession that had Log.createSubsession() called on it, but will never have
		* Log.continueSession(...) called on it due to an error. Allows the subsession to be cleaned
		* gracefully instead of being removed by the sSessionCleanupHandler forcefully later.
		* gracefully instead of being removed by the mSessionCleanupHandler forcefully later.
		*/
		public synchronized void cancelSubsession(Session subsession) {
		if (subsession == null) {
		return;
		}

		subsession.markSessionCompleted(0);
		subsession.markSessionCompleted(Session.UNDEFINED);
		endParentSessions(subsession);
		}

		@@ -197,16 +206,16 @@ public class SessionManager {
		subsession.setExecutionStartTimeMs(System.currentTimeMillis());
		Session parentSession = subsession.getParentSession();
		if (parentSession == null) {
		android.telecom.Log.d(LOGGING_TAG, "Log.continueSession was called with no session " +
		"active for method %s.", shortMethodName);
		android.util.Slog.d(LOGGING_TAG, "Log.continueSession was called with no session " +
		"active for method " + shortMethodName);
		return;
		}

		sSessionMapper.put(getCallingThreadId(), subsession);
		mSessionMapper.put(getCallingThreadId(), subsession);
		if (!subsession.isStartedFromActiveSession()) {
		android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
		android.util.Slog.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
		} else {
		android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION +
		android.util.Slog.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION +
		" (Invisible Subsession) with Method " + shortMethodName);
		}
		}
		@@ -217,30 +226,30 @@ public class SessionManager {
		*/
		public synchronized void endSession() {
		int threadId = getCallingThreadId();
		Session completedSession = sSessionMapper.get(threadId);
		Session completedSession = mSessionMapper.get(threadId);
		if (completedSession == null) {
		android.telecom.Log.w(LOGGING_TAG, "Log.endSession was called with no session active.");
		android.util.Slog.w(LOGGING_TAG, "Log.endSession was called with no session active.");
		return;
		}

		completedSession.markSessionCompleted(System.currentTimeMillis());
		if (!completedSession.isStartedFromActiveSession()) {
		android.telecom.Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
		android.util.Slog.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
		completedSession.getLocalExecutionTime() + " mS)");
		} else {
		android.telecom.Log.v(LOGGING_TAG, Session.END_SUBSESSION +
		android.util.Slog.v(LOGGING_TAG, Session.END_SUBSESSION +
		" (Invisible Subsession) (dur: " + completedSession.getLocalExecutionTime() +
		" ms)");
		}
		// Remove after completed so that reference still exists for logging the end events
		Session parentSession = completedSession.getParentSession();
		sSessionMapper.remove(threadId);
		mSessionMapper.remove(threadId);
		endParentSessions(completedSession);
		// If this subsession was started from a parent session using Log.startSession, return the
		// ThreadID back to the parent after completion.
		if (parentSession != null && !parentSession.isSessionCompleted() &&
		completedSession.isStartedFromActiveSession()) {
		sSessionMapper.put(threadId, parentSession);
		mSessionMapper.put(threadId, parentSession);
		}
		}

		@@ -262,7 +271,7 @@ public class SessionManager {
		// running time of the session.
		long fullSessionTimeMs =
		System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds();
		android.telecom.Log.v(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
		android.util.Slog.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
		+ " ms): " + subsession.toString());
		// TODO: Add analytics hook
		for (ISessionListener l : mSessionListeners) {
		@@ -272,7 +281,7 @@ public class SessionManager {
		}

		public String getSessionId() {
		Session currentSession = sSessionMapper.get(getCallingThreadId());
		Session currentSession = mSessionMapper.get(getCallingThreadId());
		return currentSession != null ? currentSession.toString() : "";
		}

		@@ -304,7 +313,7 @@ public class SessionManager {
		}

		public int getCallingThreadId() {
		return android.os.Process.myTid();
		return mCurrentThreadId.get();
		}

		@VisibleForTesting
		@@ -317,7 +326,7 @@ public class SessionManager {
		// If this occurs, then there is most likely a Session active that never had
		// Log.endSession called on it.
		for (Iterator<ConcurrentHashMap.Entry<Integer, Session>> it =
		sSessionMapper.entrySet().iterator(); it.hasNext(); ) {
		mSessionMapper.entrySet().iterator(); it.hasNext(); ) {
		ConcurrentHashMap.Entry<Integer, Session> entry = it.next();
		Session session = entry.getValue();
		if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) {
		@@ -327,9 +336,9 @@ public class SessionManager {
		}
		}
		if (isSessionsStale) {
		android.telecom.Log.w(LOGGING_TAG, logMessage);
		android.util.Slog.w(LOGGING_TAG, logMessage);
		} else {
		android.telecom.Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
		android.util.Slog.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
		}
		}