1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428
|
/*
* Copyright (C) 2016 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* 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
*/
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.telecom.Log;
import android.util.Base64;
import com.android.internal.annotations.VisibleForTesting;
import java.nio.ByteBuffer;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Iterator;
import java.util.List;
import java.util.concurrent.ConcurrentHashMap;
/**
* TODO: Create better Sessions Documentation
* @hide
*/
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.
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
private int sCodeEntryCounter = 0;
private Context mContext;
@VisibleForTesting
public ConcurrentHashMap<Integer, Session> mSessionMapper = new ConcurrentHashMap<>(100);
@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 {
long get();
}
// Overridden in tests to provide test Thread IDs
public interface ICurrentThreadId {
int get();
}
@VisibleForTesting
public ICurrentThreadId mCurrentThreadId = Process::myTid;
private ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> {
// mContext may be null in some cases, such as testing. For these cases, use the
// default value.
if (mContext == null) {
return DEFAULT_SESSION_TIMEOUT_MS;
}
return getCleanupTimeout(mContext);
};
// Usage is synchronized on this class.
private List<ISessionListener> mSessionListeners = new ArrayList<>();
public interface ISessionListener {
/**
* This method is run when a full Session has completed.
* @param sessionName The name of the Session that has completed.
* @param timeMs The time it took to complete in ms.
*/
void sessionComplete(String sessionName, long timeMs);
}
public interface ISessionIdQueryHandler {
String getSessionId();
}
public void setContext(Context context) {
mContext = context;
}
public SessionManager() {
}
private long getSessionCleanupTimeoutMs() {
return mSessionCleanupTimeoutMs.get();
}
private synchronized void resetStaleSessionTimer() {
mSessionCleanupHandler.removeCallbacksAndMessages(null);
// Will be null in Log Testing
if (mCleanStaleSessions != null) {
mSessionCleanupHandler.postDelayed(mCleanStaleSessions, getSessionCleanupTimeoutMs());
}
}
/**
* 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().
*/
public synchronized void startSession(String shortMethodName,
String callerIdentification) {
resetStaleSessionTimer();
int threadId = getCallingThreadId();
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) {
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(), false, callerIdentification);
mSessionMapper.put(threadId, newSession);
}
/**
* 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.
Log.d(LOGGING_TAG, Session.START_EXTERNAL_SESSION);
Session externalSession = new Session(Session.EXTERNAL_INDICATOR + sessionInfo.sessionId,
sessionInfo.methodPath, 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);
}
/**
* Notifies the logging system that a subsession will be run at a later point and
* allocates the resources. Returns a session object that must be used in
* Log.continueSession(...) to start the subsession.
*/
public Session createSubsession() {
return createSubsession(false);
}
private synchronized Session createSubsession(boolean isStartedFromActiveSession) {
int threadId = getCallingThreadId();
Session threadSession = mSessionMapper.get(threadId);
if (threadSession == null) {
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(),
isStartedFromActiveSession, null);
threadSession.addChild(newSubsession);
newSubsession.setParentSession(threadSession);
if (!isStartedFromActiveSession) {
Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " +
newSubsession.toString());
} else {
Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION +
" (Invisible subsession)");
}
return newSubsession;
}
/**
* Retrieve the information of the currently active Session. This information is parcelable and
* is used to create an external Session ({@link #startExternalSession(Session.Info, String)}).
* If there is no Session active, this method will return null.
*/
public synchronized Session.Info getExternalSession() {
int threadId = getCallingThreadId();
Session threadSession = mSessionMapper.get(threadId);
if (threadSession == null) {
Log.d(LOGGING_TAG, "Log.getExternalSession was called with no session " +
"active.");
return null;
}
return threadSession.getInfo();
}
/**
* 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 mSessionCleanupHandler forcefully later.
*/
public synchronized void cancelSubsession(Session subsession) {
if (subsession == null) {
return;
}
subsession.markSessionCompleted(Session.UNDEFINED);
endParentSessions(subsession);
}
/**
* Starts the subsession that was created in Log.CreateSubsession. The Log.endSession() method
* must be called at the end of this method. The full session will complete when all
* subsessions are completed.
*/
public synchronized void continueSession(Session subsession, String shortMethodName) {
if (subsession == null) {
return;
}
resetStaleSessionTimer();
subsession.setShortMethodName(shortMethodName);
subsession.setExecutionStartTimeMs(System.currentTimeMillis());
Session parentSession = subsession.getParentSession();
if (parentSession == null) {
Log.i(LOGGING_TAG, "Log.continueSession was called with no session " +
"active for method " + shortMethodName);
return;
}
mSessionMapper.put(getCallingThreadId(), subsession);
if (!subsession.isStartedFromActiveSession()) {
Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION);
} else {
Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION +
" (Invisible Subsession) with Method " + shortMethodName);
}
}
/**
* Ends the current session/subsession. Must be called after a Log.startSession(...) and
* Log.continueSession(...) call.
*/
public synchronized void endSession() {
int threadId = getCallingThreadId();
Session completedSession = mSessionMapper.get(threadId);
if (completedSession == null) {
Log.w(LOGGING_TAG, "Log.endSession was called with no session active.");
return;
}
completedSession.markSessionCompleted(System.currentTimeMillis());
if (!completedSession.isStartedFromActiveSession()) {
Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " +
completedSession.getLocalExecutionTime() + " mS)");
} else {
Log.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();
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()) {
mSessionMapper.put(threadId, parentSession);
}
}
// Recursively deletes all complete parent sessions of the current subsession if it is a leaf.
private void endParentSessions(Session subsession) {
// Session is not completed or not currently a leaf, so we can not remove because a child is
// still running
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();
Log.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs
+ " ms): " + subsession.toString());
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() : "";
}
public synchronized void registerSessionListener(ISessionListener l) {
if (l != null) {
mSessionListeners.add(l);
}
}
private synchronized String getNextSessionID() {
Integer nextId = sCodeEntryCounter++;
if (nextId >= SESSION_ID_ROLLOVER_THRESHOLD) {
restartSessionCounter();
nextId = sCodeEntryCounter++;
}
return getBase64Encoding(nextId);
}
private synchronized void restartSessionCounter() {
sCodeEntryCounter = 0;
}
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);
}
private int getCallingThreadId() {
return mCurrentThreadId.get();
}
@VisibleForTesting
public synchronized void cleanupStaleSessions(long timeoutMs) {
String logMessage = "Stale Sessions Cleaned:\n";
boolean isSessionsStale = false;
long currentTimeMs = System.currentTimeMillis();
// Remove references that are in the Session Mapper (causing GC to occur) on
// sessions that are lasting longer than LOGGING_SESSION_TIMEOUT_MS.
// 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 =
mSessionMapper.entrySet().iterator(); it.hasNext(); ) {
ConcurrentHashMap.Entry<Integer, Session> entry = it.next();
Session session = entry.getValue();
if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) {
it.remove();
logMessage += session.printFullSessionTree() + "\n";
isSessionsStale = true;
}
}
if (isSessionsStale) {
Log.w(LOGGING_TAG, logMessage);
} else {
Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned...");
}
}
/**
* Returns the amount of time after a Logging session has been started that Telecom is set to
* perform a sweep to check and make sure that the session is still not incomplete (stale).
*/
private long getCleanupTimeout(Context context) {
return Settings.Secure.getLong(context.getContentResolver(), TIMEOUTS_PREFIX +
"stale_session_cleanup_timeout_millis", DEFAULT_SESSION_TIMEOUT_MS);
}
}
|