Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame^] | 1 | /* |
| 2 | * Copyright (C) 2016 The Android Open Source Project |
| 3 | * |
| 4 | * Licensed under the Apache License, Version 2.0 (the "License"); |
| 5 | * you may not use this file except in compliance with the License. |
| 6 | * You may obtain a copy of the License at |
| 7 | * |
| 8 | * http://www.apache.org/licenses/LICENSE-2.0 |
| 9 | * |
| 10 | * Unless required by applicable law or agreed to in writing, software |
| 11 | * distributed under the License is distributed on an "AS IS" BASIS, |
| 12 | * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 13 | * See the License for the specific language governing permissions and |
| 14 | * limitations under the License |
| 15 | */ |
| 16 | |
| 17 | package android.telecom.Logging; |
| 18 | |
| 19 | import android.content.Context; |
| 20 | import android.os.Handler; |
| 21 | import android.os.Looper; |
| 22 | import android.provider.Settings; |
| 23 | import android.util.Base64; |
| 24 | |
| 25 | import com.android.internal.annotations.VisibleForTesting; |
| 26 | |
| 27 | import java.nio.ByteBuffer; |
| 28 | import java.util.ArrayList; |
| 29 | import java.util.Arrays; |
| 30 | import java.util.Iterator; |
| 31 | import java.util.List; |
| 32 | import java.util.concurrent.ConcurrentHashMap; |
| 33 | |
| 34 | /** |
| 35 | * TODO: Create better Sessions Documentation |
| 36 | * @hide |
| 37 | */ |
| 38 | |
| 39 | public class SessionManager { |
| 40 | |
| 41 | // Currently using 3 letters, So don't exceed 64^3 |
| 42 | private static final long SESSION_ID_ROLLOVER_THRESHOLD = 262144; |
| 43 | |
| 44 | // This parameter can be overridden in Telecom's Timeouts class. |
| 45 | public static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds |
| 46 | |
| 47 | private static String LOGGING_TAG = "Logging"; |
| 48 | |
| 49 | private static final String TIMEOUTS_PREFIX = "telecom."; |
| 50 | |
| 51 | // Synchronized in all method calls |
| 52 | private int sCodeEntryCounter = 0; |
| 53 | private Context mContext; |
| 54 | |
| 55 | @VisibleForTesting |
| 56 | public ConcurrentHashMap<Integer, Session> sSessionMapper = new ConcurrentHashMap<>(100); |
| 57 | @VisibleForTesting |
| 58 | public Handler sSessionCleanupHandler = new Handler(Looper.getMainLooper()); |
| 59 | @VisibleForTesting |
| 60 | public java.lang.Runnable sCleanStaleSessions = () -> |
| 61 | cleanupStaleSessions(getSessionCleanupTimeoutMs()); |
| 62 | |
| 63 | // Overridden in LogTest to skip query to ContentProvider |
| 64 | private interface ISessionCleanupTimeoutMs { |
| 65 | long get(); |
| 66 | } |
| 67 | |
| 68 | @VisibleForTesting |
| 69 | public ISessionCleanupTimeoutMs sSessionCleanupTimeoutMs = () -> { |
| 70 | // mContext may be null in some cases, such as testing. For these cases, use the |
| 71 | // default value. |
| 72 | if (mContext == null) { |
| 73 | return DEFAULT_SESSION_TIMEOUT_MS; |
| 74 | } |
| 75 | return getCleanupTimeout(mContext); |
| 76 | }; |
| 77 | |
| 78 | // Usage is synchronized on this class. |
| 79 | private List<ISessionListener> mSessionListeners = new ArrayList<>(); |
| 80 | |
| 81 | public interface ISessionListener { |
| 82 | /** |
| 83 | * This method is run when a full Session has completed. |
| 84 | * @param sessionName The name of the Session that has completed. |
| 85 | * @param timeMs The time it took to complete in ms. |
| 86 | */ |
| 87 | void sessionComplete(String sessionName, long timeMs); |
| 88 | } |
| 89 | |
| 90 | public interface ISessionIdQueryHandler { |
| 91 | String getSessionId(); |
| 92 | } |
| 93 | |
| 94 | public void setContext(Context context) { |
| 95 | mContext = context; |
| 96 | } |
| 97 | |
| 98 | public SessionManager() { |
| 99 | } |
| 100 | |
| 101 | private long getSessionCleanupTimeoutMs() { |
| 102 | return sSessionCleanupTimeoutMs.get(); |
| 103 | } |
| 104 | |
| 105 | private synchronized void resetStaleSessionTimer() { |
| 106 | sSessionCleanupHandler.removeCallbacksAndMessages(null); |
| 107 | // Will be null in Log Testing |
| 108 | if (sCleanStaleSessions != null) { |
| 109 | sSessionCleanupHandler.postDelayed(sCleanStaleSessions, getSessionCleanupTimeoutMs()); |
| 110 | } |
| 111 | } |
| 112 | |
| 113 | /** |
| 114 | * Call at an entry point to the Telecom code to track the session. This code must be |
| 115 | * accompanied by a Log.endSession(). |
| 116 | */ |
| 117 | public synchronized void startSession(String shortMethodName, |
| 118 | String callerIdentification) { |
| 119 | resetStaleSessionTimer(); |
| 120 | int threadId = getCallingThreadId(); |
| 121 | Session activeSession = sSessionMapper.get(threadId); |
| 122 | // We have called startSession within an active session that has not ended... Register this |
| 123 | // session as a subsession. |
| 124 | if (activeSession != null) { |
| 125 | Session childSession = createSubsession(true); |
| 126 | continueSession(childSession, shortMethodName); |
| 127 | return; |
| 128 | } |
| 129 | Session newSession = new Session(getNextSessionID(), shortMethodName, |
| 130 | System.currentTimeMillis(), threadId, false, callerIdentification); |
| 131 | sSessionMapper.put(threadId, newSession); |
| 132 | |
| 133 | android.telecom.Log.v(LOGGING_TAG, Session.START_SESSION); |
| 134 | } |
| 135 | |
| 136 | |
| 137 | /** |
| 138 | * Notifies the logging system that a subsession will be run at a later point and |
| 139 | * allocates the resources. Returns a session object that must be used in |
| 140 | * Log.continueSession(...) to start the subsession. |
| 141 | */ |
| 142 | public Session createSubsession() { |
| 143 | return createSubsession(false); |
| 144 | } |
| 145 | |
| 146 | private synchronized Session createSubsession(boolean isStartedFromActiveSession) { |
| 147 | int threadId = getCallingThreadId(); |
| 148 | Session threadSession = sSessionMapper.get(threadId); |
| 149 | if (threadSession == null) { |
| 150 | android.telecom.Log.d(LOGGING_TAG, "Log.createSubsession was called with no session " + |
| 151 | "active."); |
| 152 | return null; |
| 153 | } |
| 154 | // Start execution time of the session will be overwritten in continueSession(...). |
| 155 | Session newSubsession = new Session(threadSession.getNextChildId(), |
| 156 | threadSession.getShortMethodName(), System.currentTimeMillis(), threadId, |
| 157 | isStartedFromActiveSession, null); |
| 158 | threadSession.addChild(newSubsession); |
| 159 | newSubsession.setParentSession(threadSession); |
| 160 | |
| 161 | if (!isStartedFromActiveSession) { |
| 162 | android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " + |
| 163 | newSubsession.toString()); |
| 164 | } else { |
| 165 | android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + |
| 166 | " (Invisible subsession)"); |
| 167 | } |
| 168 | return newSubsession; |
| 169 | } |
| 170 | |
| 171 | /** |
| 172 | * Cancels a subsession that had Log.createSubsession() called on it, but will never have |
| 173 | * Log.continueSession(...) called on it due to an error. Allows the subsession to be cleaned |
| 174 | * gracefully instead of being removed by the sSessionCleanupHandler forcefully later. |
| 175 | */ |
| 176 | public synchronized void cancelSubsession(Session subsession) { |
| 177 | if (subsession == null) { |
| 178 | return; |
| 179 | } |
| 180 | |
| 181 | subsession.markSessionCompleted(0); |
| 182 | endParentSessions(subsession); |
| 183 | } |
| 184 | |
| 185 | /** |
| 186 | * Starts the subsession that was created in Log.CreateSubsession. The Log.endSession() method |
| 187 | * must be called at the end of this method. The full session will complete when all |
| 188 | * subsessions are completed. |
| 189 | */ |
| 190 | public synchronized void continueSession(Session subsession, String shortMethodName) { |
| 191 | if (subsession == null) { |
| 192 | return; |
| 193 | } |
| 194 | resetStaleSessionTimer(); |
| 195 | String callingMethodName = subsession.getShortMethodName(); |
| 196 | subsession.setShortMethodName(callingMethodName + "->" + shortMethodName); |
| 197 | subsession.setExecutionStartTimeMs(System.currentTimeMillis()); |
| 198 | Session parentSession = subsession.getParentSession(); |
| 199 | if (parentSession == null) { |
| 200 | android.telecom.Log.d(LOGGING_TAG, "Log.continueSession was called with no session " + |
| 201 | "active for method %s.", shortMethodName); |
| 202 | return; |
| 203 | } |
| 204 | |
| 205 | sSessionMapper.put(getCallingThreadId(), subsession); |
| 206 | if (!subsession.isStartedFromActiveSession()) { |
| 207 | android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION); |
| 208 | } else { |
| 209 | android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION + |
| 210 | " (Invisible Subsession) with Method " + shortMethodName); |
| 211 | } |
| 212 | } |
| 213 | |
| 214 | /** |
| 215 | * Ends the current session/subsession. Must be called after a Log.startSession(...) and |
| 216 | * Log.continueSession(...) call. |
| 217 | */ |
| 218 | public synchronized void endSession() { |
| 219 | int threadId = getCallingThreadId(); |
| 220 | Session completedSession = sSessionMapper.get(threadId); |
| 221 | if (completedSession == null) { |
| 222 | android.telecom.Log.w(LOGGING_TAG, "Log.endSession was called with no session active."); |
| 223 | return; |
| 224 | } |
| 225 | |
| 226 | completedSession.markSessionCompleted(System.currentTimeMillis()); |
| 227 | if (!completedSession.isStartedFromActiveSession()) { |
| 228 | android.telecom.Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " + |
| 229 | completedSession.getLocalExecutionTime() + " mS)"); |
| 230 | } else { |
| 231 | android.telecom.Log.v(LOGGING_TAG, Session.END_SUBSESSION + |
| 232 | " (Invisible Subsession) (dur: " + completedSession.getLocalExecutionTime() + |
| 233 | " ms)"); |
| 234 | } |
| 235 | // Remove after completed so that reference still exists for logging the end events |
| 236 | Session parentSession = completedSession.getParentSession(); |
| 237 | sSessionMapper.remove(threadId); |
| 238 | endParentSessions(completedSession); |
| 239 | // If this subsession was started from a parent session using Log.startSession, return the |
| 240 | // ThreadID back to the parent after completion. |
| 241 | if (parentSession != null && !parentSession.isSessionCompleted() && |
| 242 | completedSession.isStartedFromActiveSession()) { |
| 243 | sSessionMapper.put(threadId, parentSession); |
| 244 | } |
| 245 | } |
| 246 | |
| 247 | // Recursively deletes all complete parent sessions of the current subsession if it is a leaf. |
| 248 | private void endParentSessions(Session subsession) { |
| 249 | // Session is not completed or not currently a leaf, so we can not remove because a child is |
| 250 | // still running |
| 251 | if (!subsession.isSessionCompleted() || subsession.getChildSessions().size() != 0) { |
| 252 | return; |
| 253 | } |
| 254 | |
| 255 | Session parentSession = subsession.getParentSession(); |
| 256 | if (parentSession != null) { |
| 257 | subsession.setParentSession(null); |
| 258 | parentSession.removeChild(subsession); |
| 259 | endParentSessions(parentSession); |
| 260 | } else { |
| 261 | // All of the subsessions have been completed and it is time to report on the full |
| 262 | // running time of the session. |
| 263 | long fullSessionTimeMs = |
| 264 | System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds(); |
| 265 | android.telecom.Log.v(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs |
| 266 | + " ms): " + subsession.toString()); |
| 267 | // TODO: Add analytics hook |
| 268 | for (ISessionListener l : mSessionListeners) { |
| 269 | l.sessionComplete(subsession.getShortMethodName(), fullSessionTimeMs); |
| 270 | } |
| 271 | } |
| 272 | } |
| 273 | |
| 274 | public String getSessionId() { |
| 275 | Session currentSession = sSessionMapper.get(getCallingThreadId()); |
| 276 | return currentSession != null ? currentSession.toString() : ""; |
| 277 | } |
| 278 | |
| 279 | public synchronized void registerSessionListener(ISessionListener l) { |
| 280 | if (l != null) { |
| 281 | mSessionListeners.add(l); |
| 282 | } |
| 283 | } |
| 284 | |
| 285 | private synchronized String getNextSessionID() { |
| 286 | Integer nextId = sCodeEntryCounter++; |
| 287 | if (nextId >= SESSION_ID_ROLLOVER_THRESHOLD) { |
| 288 | restartSessionCounter(); |
| 289 | nextId = sCodeEntryCounter++; |
| 290 | } |
| 291 | return getBase64Encoding(nextId); |
| 292 | } |
| 293 | |
| 294 | @VisibleForTesting |
| 295 | public synchronized void restartSessionCounter() { |
| 296 | sCodeEntryCounter = 0; |
| 297 | } |
| 298 | |
| 299 | @VisibleForTesting |
| 300 | public String getBase64Encoding(int number) { |
| 301 | byte[] idByteArray = ByteBuffer.allocate(4).putInt(number).array(); |
| 302 | idByteArray = Arrays.copyOfRange(idByteArray, 2, 4); |
| 303 | return Base64.encodeToString(idByteArray, Base64.NO_WRAP | Base64.NO_PADDING); |
| 304 | } |
| 305 | |
| 306 | public int getCallingThreadId() { |
| 307 | return android.os.Process.myTid(); |
| 308 | } |
| 309 | |
| 310 | @VisibleForTesting |
| 311 | private synchronized void cleanupStaleSessions(long timeoutMs) { |
| 312 | String logMessage = "Stale Sessions Cleaned:\n"; |
| 313 | boolean isSessionsStale = false; |
| 314 | long currentTimeMs = System.currentTimeMillis(); |
| 315 | // Remove references that are in the Session Mapper (causing GC to occur) on |
| 316 | // sessions that are lasting longer than LOGGING_SESSION_TIMEOUT_MS. |
| 317 | // If this occurs, then there is most likely a Session active that never had |
| 318 | // Log.endSession called on it. |
| 319 | for (Iterator<ConcurrentHashMap.Entry<Integer, Session>> it = |
| 320 | sSessionMapper.entrySet().iterator(); it.hasNext(); ) { |
| 321 | ConcurrentHashMap.Entry<Integer, Session> entry = it.next(); |
| 322 | Session session = entry.getValue(); |
| 323 | if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) { |
| 324 | it.remove(); |
| 325 | logMessage += session.printFullSessionTree() + "\n"; |
| 326 | isSessionsStale = true; |
| 327 | } |
| 328 | } |
| 329 | if (isSessionsStale) { |
| 330 | android.telecom.Log.w(LOGGING_TAG, logMessage); |
| 331 | } else { |
| 332 | android.telecom.Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned..."); |
| 333 | } |
| 334 | } |
| 335 | |
| 336 | /** |
| 337 | * Returns the amount of time after a Logging session has been started that Telecom is set to |
| 338 | * perform a sweep to check and make sure that the session is still not incomplete (stale). |
| 339 | */ |
| 340 | private long getCleanupTimeout(Context context) { |
| 341 | return Settings.Secure.getLong(context.getContentResolver(), TIMEOUTS_PREFIX + |
| 342 | "stale_session_cleanup_timeout_millis", DEFAULT_SESSION_TIMEOUT_MS); |
| 343 | } |
| 344 | } |