Merge "Add support for starting external Sessions"
am: 4ce60695f9
Change-Id: I6957c8e2846d216f77f5f6337388e1fc296511de
This commit is contained in:
@ -188,6 +188,15 @@ public class Log {
|
||||
getSessionManager().startSession(shortMethodName, callerIdentification);
|
||||
}
|
||||
|
||||
public static void startSession(Session.Info info, String shortMethodName,
|
||||
String callerIdentification) {
|
||||
getSessionManager().startSession(info, shortMethodName, callerIdentification);
|
||||
}
|
||||
|
||||
public static void startExternalSession(Session.Info sessionInfo, String shortMethodName) {
|
||||
getSessionManager().startExternalSession(sessionInfo, shortMethodName);
|
||||
}
|
||||
|
||||
public static Session createSubsession() {
|
||||
return getSessionManager().createSubsession();
|
||||
}
|
||||
|
@ -17,6 +17,11 @@
|
||||
package android.telecom.Logging;
|
||||
|
||||
import android.annotation.NonNull;
|
||||
import android.os.Parcel;
|
||||
import android.os.Parcelable;
|
||||
import android.text.TextUtils;
|
||||
|
||||
import com.android.internal.annotations.VisibleForTesting;
|
||||
|
||||
import java.util.ArrayList;
|
||||
|
||||
@ -33,12 +38,58 @@ public class Session {
|
||||
public static final String END_SUBSESSION = "END_SUBSESSION";
|
||||
public static final String END_SESSION = "END_SESSION";
|
||||
|
||||
public static final String SUBSESSION_SEPARATION_CHAR = "->";
|
||||
public static final String EXTERNAL_INDICATOR = "E-";
|
||||
|
||||
/**
|
||||
* Initial value of mExecutionEndTimeMs and the final value of {@link #getLocalExecutionTime()}
|
||||
* if the Session is canceled.
|
||||
*/
|
||||
public static final int UNDEFINED = -1;
|
||||
|
||||
public static class Info implements Parcelable {
|
||||
public final String sessionId;
|
||||
public final String shortMethodName;
|
||||
|
||||
private Info(String id, String methodName) {
|
||||
sessionId = id;
|
||||
shortMethodName = methodName;
|
||||
}
|
||||
|
||||
public static Info getInfo (Session s) {
|
||||
return new Info(s.getFullSessionId(), s.getShortMethodName());
|
||||
}
|
||||
|
||||
/** Responsible for creating Info objects for deserialized Parcels. */
|
||||
public static final Parcelable.Creator<Info> CREATOR =
|
||||
new Parcelable.Creator<Info> () {
|
||||
@Override
|
||||
public Info createFromParcel(Parcel source) {
|
||||
String id = source.readString();
|
||||
String methodName = source.readString();
|
||||
return new Info(id, methodName);
|
||||
}
|
||||
|
||||
@Override
|
||||
public Info[] newArray(int size) {
|
||||
return new Info[size];
|
||||
}
|
||||
};
|
||||
|
||||
/** {@inheritDoc} */
|
||||
@Override
|
||||
public int describeContents() {
|
||||
return 0;
|
||||
}
|
||||
|
||||
/** Writes Info object into a Parcel. */
|
||||
@Override
|
||||
public void writeToParcel(Parcel destination, int flags) {
|
||||
destination.writeString(sessionId);
|
||||
destination.writeString(shortMethodName);
|
||||
}
|
||||
}
|
||||
|
||||
private String mSessionId;
|
||||
private String mShortMethodName;
|
||||
private long mExecutionStartTimeMs;
|
||||
@ -46,6 +97,7 @@ public class Session {
|
||||
private Session mParentSession;
|
||||
private ArrayList<Session> mChildSessions;
|
||||
private boolean mIsCompleted = false;
|
||||
private boolean mIsExternal = false;
|
||||
private int mChildCounter = 0;
|
||||
// True if this is a subsession that has been started from the same thread as the parent
|
||||
// session. This can happen if Log.startSession(...) is called multiple times on the same
|
||||
@ -56,8 +108,11 @@ public class Session {
|
||||
// Optionally provided info about the method/class/component that started the session in order
|
||||
// to make Logging easier. This info will be provided in parentheses along with the session.
|
||||
private String mOwnerInfo;
|
||||
// Cache Full Method path so that recursive population of the full method path only needs to
|
||||
// be calculated once.
|
||||
private String mFullMethodPathCache;
|
||||
|
||||
public Session(String sessionId, String shortMethodName, long startTimeMs, long threadID,
|
||||
public Session(String sessionId, String shortMethodName, long startTimeMs,
|
||||
boolean isStartedFromActiveSession, String ownerInfo) {
|
||||
setSessionId(sessionId);
|
||||
setShortMethodName(shortMethodName);
|
||||
@ -86,6 +141,14 @@ public class Session {
|
||||
mShortMethodName = shortMethodName;
|
||||
}
|
||||
|
||||
public void setIsExternal(boolean isExternal) {
|
||||
mIsExternal = isExternal;
|
||||
}
|
||||
|
||||
public boolean isExternal() {
|
||||
return mIsExternal;
|
||||
}
|
||||
|
||||
public void setParentSession(Session parentSession) {
|
||||
mParentSession = parentSession;
|
||||
}
|
||||
@ -126,6 +189,15 @@ public class Session {
|
||||
return mIsStartedFromActiveSession;
|
||||
}
|
||||
|
||||
public Info getInfo() {
|
||||
return Info.getInfo(this);
|
||||
}
|
||||
|
||||
@VisibleForTesting
|
||||
public String getSessionId() {
|
||||
return mSessionId;
|
||||
}
|
||||
|
||||
// Mark this session complete. This will be deleted by Log when all subsessions are complete
|
||||
// as well.
|
||||
public void markSessionCompleted(long executionEndTimeMs) {
|
||||
@ -186,6 +258,38 @@ public class Session {
|
||||
}
|
||||
}
|
||||
|
||||
// Recursively concatenate mShortMethodName with the parent Sessions to create full method
|
||||
// path. Caches this string so that multiple calls for the path will be quick.
|
||||
public String getFullMethodPath() {
|
||||
StringBuilder sb = new StringBuilder();
|
||||
getFullMethodPath(sb);
|
||||
return sb.toString();
|
||||
}
|
||||
|
||||
private synchronized void getFullMethodPath(StringBuilder sb) {
|
||||
// Don't calculate if we have already figured it out!
|
||||
if (!TextUtils.isEmpty(mFullMethodPathCache)) {
|
||||
sb.append(mFullMethodPathCache);
|
||||
return;
|
||||
}
|
||||
Session parentSession = getParentSession();
|
||||
boolean isSessionStarted = false;
|
||||
if (parentSession != null) {
|
||||
// Check to see if the session has been renamed yet. If it has not, then the session
|
||||
// has not been continued.
|
||||
isSessionStarted = !mShortMethodName.equals(parentSession.mShortMethodName);
|
||||
parentSession.getFullMethodPath(sb);
|
||||
sb.append(SUBSESSION_SEPARATION_CHAR);
|
||||
}
|
||||
sb.append(mShortMethodName);
|
||||
|
||||
if(isSessionStarted) {
|
||||
// Cache this value so that we do not have to do this work next time!
|
||||
// We do not cache the value if the session being evaluated hasn't been continued yet.
|
||||
mFullMethodPathCache = sb.toString();
|
||||
}
|
||||
}
|
||||
|
||||
@Override
|
||||
public int hashCode() {
|
||||
int result = mSessionId != null ? mSessionId.hashCode() : 0;
|
||||
@ -238,7 +342,7 @@ public class Session {
|
||||
return mParentSession.toString();
|
||||
} else {
|
||||
StringBuilder methodName = new StringBuilder();
|
||||
methodName.append(mShortMethodName);
|
||||
methodName.append(getFullMethodPath());
|
||||
if (mOwnerInfo != null && !mOwnerInfo.isEmpty()) {
|
||||
methodName.append("(InCall package: ");
|
||||
methodName.append(mOwnerInfo);
|
||||
|
@ -21,6 +21,7 @@ import android.os.Handler;
|
||||
import android.os.Looper;
|
||||
import android.os.Process;
|
||||
import android.provider.Settings;
|
||||
import android.telecom.Log;
|
||||
import android.util.Base64;
|
||||
|
||||
import com.android.internal.annotations.VisibleForTesting;
|
||||
@ -41,12 +42,9 @@ public class SessionManager {
|
||||
|
||||
// Currently using 3 letters, So don't exceed 64^3
|
||||
private static final long SESSION_ID_ROLLOVER_THRESHOLD = 262144;
|
||||
|
||||
// This parameter can be overridden in Telecom's Timeouts class.
|
||||
public static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds
|
||||
|
||||
private static String LOGGING_TAG = "Logging";
|
||||
|
||||
private static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds
|
||||
private static final String LOGGING_TAG = "Logging";
|
||||
private static final String TIMEOUTS_PREFIX = "telecom.";
|
||||
|
||||
// Synchronized in all method calls
|
||||
@ -56,10 +54,9 @@ public class SessionManager {
|
||||
@VisibleForTesting
|
||||
public ConcurrentHashMap<Integer, Session> mSessionMapper = new ConcurrentHashMap<>(100);
|
||||
@VisibleForTesting
|
||||
public Handler mSessionCleanupHandler = new Handler(Looper.getMainLooper());
|
||||
@VisibleForTesting
|
||||
public java.lang.Runnable mCleanStaleSessions = () ->
|
||||
cleanupStaleSessions(getSessionCleanupTimeoutMs());
|
||||
private Handler mSessionCleanupHandler = new Handler(Looper.getMainLooper());
|
||||
|
||||
// Overridden in LogTest to skip query to ContentProvider
|
||||
private interface ISessionCleanupTimeoutMs {
|
||||
@ -74,8 +71,7 @@ public class SessionManager {
|
||||
@VisibleForTesting
|
||||
public ICurrentThreadId mCurrentThreadId = Process::myTid;
|
||||
|
||||
@VisibleForTesting
|
||||
public ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> {
|
||||
private ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> {
|
||||
// mContext may be null in some cases, such as testing. For these cases, use the
|
||||
// default value.
|
||||
if (mContext == null) {
|
||||
@ -119,6 +115,21 @@ public class SessionManager {
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* Determines whether or not to start a new session or continue an existing session based on
|
||||
* the {@link Session.Info} info passed into startSession. If info is null, a new Session is
|
||||
* created. This code must be accompanied by endSession() at the end of the Session.
|
||||
*/
|
||||
public synchronized void startSession(Session.Info info, String shortMethodName,
|
||||
String callerIdentification) {
|
||||
// Start a new session normally if the
|
||||
if(info == null) {
|
||||
startSession(shortMethodName, callerIdentification);
|
||||
} else {
|
||||
startExternalSession(info, shortMethodName);
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* Call at an entry point to the Telecom code to track the session. This code must be
|
||||
* accompanied by a Log.endSession().
|
||||
@ -134,14 +145,54 @@ public class SessionManager {
|
||||
Session childSession = createSubsession(true);
|
||||
continueSession(childSession, shortMethodName);
|
||||
return;
|
||||
} else {
|
||||
// Only Log that we are starting the parent session.
|
||||
Log.d(LOGGING_TAG, Session.START_SESSION);
|
||||
}
|
||||
Session newSession = new Session(getNextSessionID(), shortMethodName,
|
||||
System.currentTimeMillis(), threadId, false, callerIdentification);
|
||||
System.currentTimeMillis(), false, callerIdentification);
|
||||
mSessionMapper.put(threadId, newSession);
|
||||
|
||||
android.util.Slog.v(LOGGING_TAG, Session.START_SESSION);
|
||||
}
|
||||
|
||||
/**
|
||||
* Registers an external Session with the Manager using that external Session's sessionInfo.
|
||||
* Log.endSession will still need to be called at the end of the session.
|
||||
* @param sessionInfo Describes the external Session's information.
|
||||
* @param shortMethodName The method name of the new session that is being started.
|
||||
*/
|
||||
public synchronized void startExternalSession(Session.Info sessionInfo,
|
||||
String shortMethodName) {
|
||||
if(sessionInfo == null) {
|
||||
return;
|
||||
}
|
||||
|
||||
int threadId = getCallingThreadId();
|
||||
Session threadSession = mSessionMapper.get(threadId);
|
||||
if (threadSession != null) {
|
||||
// We should never get into a situation where there is already an active session AND
|
||||
// an external session is added. We are just using that active session.
|
||||
Log.w(LOGGING_TAG, "trying to start an external session with a session " +
|
||||
"already active.");
|
||||
return;
|
||||
}
|
||||
|
||||
// Create Session from Info and add to the sessionMapper under this ID.
|
||||
Session externalSession = new Session(Session.EXTERNAL_INDICATOR + sessionInfo.sessionId,
|
||||
sessionInfo.shortMethodName, System.currentTimeMillis(),
|
||||
false /*isStartedFromActiveSession*/, null);
|
||||
externalSession.setIsExternal(true);
|
||||
// Mark the external session as already completed, since we have no way of knowing when
|
||||
// the external session actually has completed.
|
||||
externalSession.markSessionCompleted(Session.UNDEFINED);
|
||||
// Track the external session with the SessionMapper so that we can create and continue
|
||||
// an active subsession based on it.
|
||||
mSessionMapper.put(threadId, externalSession);
|
||||
// Create a subsession from this external Session parent node
|
||||
Session childSession = createSubsession();
|
||||
continueSession(childSession, shortMethodName);
|
||||
|
||||
Log.d(LOGGING_TAG, Session.START_SESSION);
|
||||
}
|
||||
|
||||
/**
|
||||
* Notifies the logging system that a subsession will be run at a later point and
|
||||
@ -156,22 +207,22 @@ public class SessionManager {
|
||||
int threadId = getCallingThreadId();
|
||||
Session threadSession = mSessionMapper.get(threadId);
|
||||
if (threadSession == null) {
|
||||
android.util.Slog.d(LOGGING_TAG, "Log.createSubsession was called with no session " +
|
||||
Log.d(LOGGING_TAG, "Log.createSubsession was called with no session " +
|
||||
"active.");
|
||||
return null;
|
||||
}
|
||||
// Start execution time of the session will be overwritten in continueSession(...).
|
||||
Session newSubsession = new Session(threadSession.getNextChildId(),
|
||||
threadSession.getShortMethodName(), System.currentTimeMillis(), threadId,
|
||||
threadSession.getShortMethodName(), System.currentTimeMillis(),
|
||||
isStartedFromActiveSession, null);
|
||||
threadSession.addChild(newSubsession);
|
||||
newSubsession.setParentSession(threadSession);
|
||||
|
||||
if (!isStartedFromActiveSession) {
|
||||
android.util.Slog.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
|
||||
Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
|
||||
newSubsession.toString());
|
||||
} else {
|
||||
android.util.Slog.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
|
||||
Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
|
||||
" (Invisible subsession)");
|
||||
}
|
||||
return newSubsession;
|
||||
@ -201,21 +252,20 @@ public class SessionManager {
|
||||
return;
|
||||
}
|
||||
resetStaleSessionTimer();
|
||||
String callingMethodName = subsession.getShortMethodName();
|
||||
subsession.setShortMethodName(callingMethodName + "->" + shortMethodName);
|
||||
subsession.setShortMethodName(shortMethodName);
|
||||
subsession.setExecutionStartTimeMs(System.currentTimeMillis());
|
||||
Session parentSession = subsession.getParentSession();
|
||||
if (parentSession == null) {
|
||||
android.util.Slog.d(LOGGING_TAG, "Log.continueSession was called with no session " +
|
||||
Log.i(LOGGING_TAG, "Log.continueSession was called with no session " +
|
||||
"active for method " + shortMethodName);
|
||||
return;
|
||||
}
|
||||
|
||||
mSessionMapper.put(getCallingThreadId(), subsession);
|
||||
if (!subsession.isStartedFromActiveSession()) {
|
||||
android.util.Slog.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
|
||||
Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
|
||||
} else {
|
||||
android.util.Slog.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION +
|
||||
Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION +
|
||||
" (Invisible Subsession) with Method " + shortMethodName);
|
||||
}
|
||||
}
|
||||
@ -228,16 +278,16 @@ public class SessionManager {
|
||||
int threadId = getCallingThreadId();
|
||||
Session completedSession = mSessionMapper.get(threadId);
|
||||
if (completedSession == null) {
|
||||
android.util.Slog.w(LOGGING_TAG, "Log.endSession was called with no session active.");
|
||||
Log.w(LOGGING_TAG, "Log.endSession was called with no session active.");
|
||||
return;
|
||||
}
|
||||
|
||||
completedSession.markSessionCompleted(System.currentTimeMillis());
|
||||
if (!completedSession.isStartedFromActiveSession()) {
|
||||
android.util.Slog.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
|
||||
Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
|
||||
completedSession.getLocalExecutionTime() + " mS)");
|
||||
} else {
|
||||
android.util.Slog.v(LOGGING_TAG, Session.END_SUBSESSION +
|
||||
Log.v(LOGGING_TAG, Session.END_SUBSESSION +
|
||||
" (Invisible Subsession) (dur: " + completedSession.getLocalExecutionTime() +
|
||||
" ms)");
|
||||
}
|
||||
@ -260,25 +310,37 @@ public class SessionManager {
|
||||
if (!subsession.isSessionCompleted() || subsession.getChildSessions().size() != 0) {
|
||||
return;
|
||||
}
|
||||
|
||||
Session parentSession = subsession.getParentSession();
|
||||
if (parentSession != null) {
|
||||
subsession.setParentSession(null);
|
||||
parentSession.removeChild(subsession);
|
||||
// Report the child session of the external session as being complete to the listeners,
|
||||
// not the external session itself.
|
||||
if (parentSession.isExternal()) {
|
||||
long fullSessionTimeMs =
|
||||
System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds();
|
||||
notifySessionCompleteListeners(subsession.getShortMethodName(), fullSessionTimeMs);
|
||||
}
|
||||
endParentSessions(parentSession);
|
||||
} else {
|
||||
// All of the subsessions have been completed and it is time to report on the full
|
||||
// running time of the session.
|
||||
long fullSessionTimeMs =
|
||||
System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds();
|
||||
android.util.Slog.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
|
||||
Log.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
|
||||
+ " ms): " + subsession.toString());
|
||||
for (ISessionListener l : mSessionListeners) {
|
||||
l.sessionComplete(subsession.getShortMethodName(), fullSessionTimeMs);
|
||||
if (!subsession.isExternal()) {
|
||||
notifySessionCompleteListeners(subsession.getShortMethodName(), fullSessionTimeMs);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
private void notifySessionCompleteListeners(String methodName, long sessionTimeMs) {
|
||||
for (ISessionListener l : mSessionListeners) {
|
||||
l.sessionComplete(methodName, sessionTimeMs);
|
||||
}
|
||||
}
|
||||
|
||||
public String getSessionId() {
|
||||
Session currentSession = mSessionMapper.get(getCallingThreadId());
|
||||
return currentSession != null ? currentSession.toString() : "";
|
||||
@ -299,24 +361,22 @@ public class SessionManager {
|
||||
return getBase64Encoding(nextId);
|
||||
}
|
||||
|
||||
@VisibleForTesting
|
||||
public synchronized void restartSessionCounter() {
|
||||
private synchronized void restartSessionCounter() {
|
||||
sCodeEntryCounter = 0;
|
||||
}
|
||||
|
||||
@VisibleForTesting
|
||||
public String getBase64Encoding(int number) {
|
||||
private String getBase64Encoding(int number) {
|
||||
byte[] idByteArray = ByteBuffer.allocate(4).putInt(number).array();
|
||||
idByteArray = Arrays.copyOfRange(idByteArray, 2, 4);
|
||||
return Base64.encodeToString(idByteArray, Base64.NO_WRAP | Base64.NO_PADDING);
|
||||
}
|
||||
|
||||
public int getCallingThreadId() {
|
||||
private int getCallingThreadId() {
|
||||
return mCurrentThreadId.get();
|
||||
}
|
||||
|
||||
@VisibleForTesting
|
||||
private synchronized void cleanupStaleSessions(long timeoutMs) {
|
||||
public synchronized void cleanupStaleSessions(long timeoutMs) {
|
||||
String logMessage = "Stale Sessions Cleaned:\n";
|
||||
boolean isSessionsStale = false;
|
||||
long currentTimeMs = System.currentTimeMillis();
|
||||
@ -335,9 +395,9 @@ public class SessionManager {
|
||||
}
|
||||
}
|
||||
if (isSessionsStale) {
|
||||
android.util.Slog.w(LOGGING_TAG, logMessage);
|
||||
Log.w(LOGGING_TAG, logMessage);
|
||||
} else {
|
||||
android.util.Slog.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
|
||||
Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
|
||||
}
|
||||
}
|
||||
|
||||
|
Reference in New Issue
Block a user