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.annotation.NonNull; |
| 20 | import android.telecom.Log; |
| 21 | import android.text.TextUtils; |
| 22 | |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 23 | import com.android.internal.annotations.VisibleForTesting; |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 24 | import com.android.internal.util.IndentingPrintWriter; |
| 25 | |
| 26 | import java.text.DateFormat; |
| 27 | import java.text.SimpleDateFormat; |
| 28 | import java.util.ArrayList; |
| 29 | import java.util.Collections; |
| 30 | import java.util.Date; |
| 31 | import java.util.HashMap; |
| 32 | import java.util.IllegalFormatException; |
| 33 | import java.util.LinkedList; |
| 34 | import java.util.List; |
| 35 | import java.util.Locale; |
| 36 | import java.util.Map; |
| 37 | import java.util.concurrent.LinkedBlockingQueue; |
| 38 | |
| 39 | /** |
| 40 | * A utility class that provides the ability to define Events that a subsystem deems important, and |
| 41 | * then relate those events to other events so that information can be extracted. For example, a |
| 42 | * START and FINISH event can be defined and when a START and then FINISH occurs in a sequence, the |
| 43 | * time it took to complete that sequence can be saved to be retrieved later. |
| 44 | * @hide |
| 45 | */ |
| 46 | |
| 47 | public class EventManager { |
| 48 | |
| 49 | public static final String TAG = "Logging.Events"; |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 50 | @VisibleForTesting |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 51 | public static final int DEFAULT_EVENTS_TO_CACHE = 10; // Arbitrarily chosen. |
| 52 | |
| 53 | public interface Loggable { |
| 54 | /** |
| 55 | * @return a unique String ID that will allow the Event to be recognized later in the logs. |
| 56 | */ |
| 57 | String getId(); |
| 58 | |
| 59 | /** |
| 60 | * @return Formatted information about the state that will be printed out later in the logs. |
| 61 | */ |
| 62 | String getDescription(); |
| 63 | } |
| 64 | |
| 65 | private final Map<Loggable, EventRecord> mCallEventRecordMap = new HashMap<>(); |
| 66 | private LinkedBlockingQueue<EventRecord> mEventRecords = |
| 67 | new LinkedBlockingQueue<>(DEFAULT_EVENTS_TO_CACHE); |
| 68 | |
| 69 | private List<EventListener> mEventListeners = new ArrayList<>(); |
| 70 | |
| 71 | public interface EventListener { |
| 72 | /** |
| 73 | * Notifies the implementation of this method that a new event record has been added. |
| 74 | * @param eventRecord Reference to the recently added EventRecord |
| 75 | */ |
| 76 | void eventRecordAdded(EventRecord eventRecord); |
| 77 | } |
| 78 | |
| 79 | private SessionManager.ISessionIdQueryHandler mSessionIdHandler; |
| 80 | /** |
| 81 | * Maps from request events to a list of possible response events. Used to track |
| 82 | * end-to-end timing for critical user-facing operations in Telecom. |
| 83 | */ |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 84 | private final Map<String, List<TimedEventPair>> requestResponsePairs = new HashMap<>(); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 85 | |
| 86 | private static final Object mSync = new Object(); |
| 87 | |
| 88 | /** |
| 89 | * Stores the various events. |
| 90 | * Also stores all request-response pairs amongst the events. |
| 91 | */ |
| 92 | public static class TimedEventPair { |
| 93 | private static final long DEFAULT_TIMEOUT = 3000L; |
| 94 | |
| 95 | String mRequest; |
| 96 | String mResponse; |
| 97 | String mName; |
| 98 | long mTimeoutMillis = DEFAULT_TIMEOUT; |
| 99 | |
| 100 | public TimedEventPair(String request, String response, String name) { |
| 101 | this.mRequest = request; |
| 102 | this.mResponse = response; |
| 103 | this.mName = name; |
| 104 | } |
| 105 | |
| 106 | public TimedEventPair(String request, String response, String name, long timeoutMillis) { |
| 107 | this.mRequest = request; |
| 108 | this.mResponse = response; |
| 109 | this.mName = name; |
| 110 | this.mTimeoutMillis = timeoutMillis; |
| 111 | } |
| 112 | } |
| 113 | |
| 114 | public void addRequestResponsePair(TimedEventPair p) { |
| 115 | if (requestResponsePairs.containsKey(p.mRequest)) { |
| 116 | requestResponsePairs.get(p.mRequest).add(p); |
| 117 | } else { |
| 118 | ArrayList<TimedEventPair> responses = new ArrayList<>(); |
| 119 | responses.add(p); |
| 120 | requestResponsePairs.put(p.mRequest, responses); |
| 121 | } |
| 122 | } |
| 123 | |
| 124 | public static class Event { |
| 125 | public String eventId; |
| 126 | public String sessionId; |
| 127 | public long time; |
| 128 | public Object data; |
| 129 | |
| 130 | public Event(String eventId, String sessionId, long time, Object data) { |
| 131 | this.eventId = eventId; |
| 132 | this.sessionId = sessionId; |
| 133 | this.time = time; |
| 134 | this.data = data; |
| 135 | } |
| 136 | } |
| 137 | |
| 138 | public class EventRecord { |
| 139 | public class EventTiming extends TimedEvent<String> { |
| 140 | public String name; |
| 141 | public long time; |
| 142 | |
| 143 | public EventTiming(String name, long time) { |
| 144 | this.name = name; |
| 145 | this.time = time; |
| 146 | } |
| 147 | |
| 148 | public String getKey() { |
| 149 | return name; |
| 150 | } |
| 151 | |
| 152 | public long getTime() { |
| 153 | return time; |
| 154 | } |
| 155 | } |
| 156 | |
| 157 | private class PendingResponse { |
| 158 | String requestEventId; |
| 159 | long requestEventTimeMillis; |
| 160 | long timeoutMillis; |
| 161 | String name; |
| 162 | |
| 163 | public PendingResponse(String requestEventId, long requestEventTimeMillis, |
| 164 | long timeoutMillis, String name) { |
| 165 | this.requestEventId = requestEventId; |
| 166 | this.requestEventTimeMillis = requestEventTimeMillis; |
| 167 | this.timeoutMillis = timeoutMillis; |
| 168 | this.name = name; |
| 169 | } |
| 170 | } |
| 171 | |
| 172 | private final DateFormat sDateFormat = new SimpleDateFormat("HH:mm:ss.SSS"); |
| 173 | private final List<Event> mEvents = new LinkedList<>(); |
| 174 | private final Loggable mRecordEntry; |
| 175 | |
| 176 | public EventRecord(Loggable recordEntry) { |
| 177 | mRecordEntry = recordEntry; |
| 178 | } |
| 179 | |
| 180 | public Loggable getRecordEntry() { |
| 181 | return mRecordEntry; |
| 182 | } |
| 183 | |
| 184 | public void addEvent(String event, String sessionId, Object data) { |
| 185 | mEvents.add(new Event(event, sessionId, System.currentTimeMillis(), data)); |
| 186 | Log.i("Event", "RecordEntry %s: %s, %s", mRecordEntry.getId(), event, data); |
| 187 | } |
| 188 | |
| 189 | public List<Event> getEvents() { |
| 190 | return mEvents; |
| 191 | } |
| 192 | |
| 193 | public List<EventTiming> extractEventTimings() { |
| 194 | if (mEvents == null) { |
| 195 | return Collections.emptyList(); |
| 196 | } |
| 197 | |
| 198 | LinkedList<EventTiming> result = new LinkedList<>(); |
| 199 | Map<String, PendingResponse> pendingResponses = new HashMap<>(); |
| 200 | for (Event event : mEvents) { |
| 201 | if (requestResponsePairs.containsKey(event.eventId)) { |
| 202 | // This event expects a response, so add that expected response to the maps |
| 203 | // of pending events. |
| 204 | for (EventManager.TimedEventPair p : requestResponsePairs.get(event.eventId)) { |
| 205 | pendingResponses.put(p.mResponse, new PendingResponse(event.eventId, |
| 206 | event.time, p.mTimeoutMillis, p.mName)); |
| 207 | } |
| 208 | } |
| 209 | |
| 210 | PendingResponse pendingResponse = pendingResponses.remove(event.eventId); |
| 211 | if (pendingResponse != null) { |
| 212 | long elapsedTime = event.time - pendingResponse.requestEventTimeMillis; |
| 213 | if (elapsedTime < pendingResponse.timeoutMillis) { |
| 214 | result.add(new EventTiming(pendingResponse.name, elapsedTime)); |
| 215 | } |
| 216 | } |
| 217 | } |
| 218 | |
| 219 | return result; |
| 220 | } |
| 221 | |
| 222 | public void dump(IndentingPrintWriter pw) { |
| 223 | pw.print(mRecordEntry.getDescription()); |
| 224 | |
| 225 | pw.increaseIndent(); |
| 226 | for (Event event : mEvents) { |
| 227 | pw.print(sDateFormat.format(new Date(event.time))); |
| 228 | pw.print(" - "); |
| 229 | pw.print(event.eventId); |
| 230 | if (event.data != null) { |
| 231 | pw.print(" ("); |
| 232 | Object data = event.data; |
| 233 | |
| 234 | if (data instanceof Loggable) { |
| 235 | // If the data is another Loggable, then change the data to the |
| 236 | // Entry's Event ID instead. |
| 237 | EventRecord record = mCallEventRecordMap.get(data); |
| 238 | if (record != null) { |
| 239 | data = "RecordEntry " + record.mRecordEntry.getId(); |
| 240 | } |
| 241 | } |
| 242 | |
| 243 | pw.print(data); |
| 244 | pw.print(")"); |
| 245 | } |
| 246 | if (!TextUtils.isEmpty(event.sessionId)) { |
| 247 | pw.print(":"); |
| 248 | pw.print(event.sessionId); |
| 249 | } |
| 250 | pw.println(); |
| 251 | } |
| 252 | |
| 253 | pw.println("Timings (average for this call, milliseconds):"); |
| 254 | pw.increaseIndent(); |
| 255 | Map<String, Double> avgEventTimings = EventTiming.averageTimings(extractEventTimings()); |
| 256 | List<String> eventNames = new ArrayList<>(avgEventTimings.keySet()); |
| 257 | Collections.sort(eventNames); |
| 258 | for (String eventName : eventNames) { |
| 259 | pw.printf("%s: %.2f\n", eventName, avgEventTimings.get(eventName)); |
| 260 | } |
| 261 | pw.decreaseIndent(); |
| 262 | pw.decreaseIndent(); |
| 263 | } |
| 264 | } |
| 265 | |
| 266 | public EventManager(@NonNull SessionManager.ISessionIdQueryHandler l) { |
| 267 | mSessionIdHandler = l; |
| 268 | } |
| 269 | |
| 270 | public void event(Loggable recordEntry, String event, Object data) { |
| 271 | String currentSessionID = mSessionIdHandler.getSessionId(); |
| 272 | |
| 273 | if (recordEntry == null) { |
| 274 | Log.i(TAG, "Non-call EVENT: %s, %s", event, data); |
| 275 | return; |
| 276 | } |
| 277 | synchronized (mEventRecords) { |
| 278 | if (!mCallEventRecordMap.containsKey(recordEntry)) { |
| 279 | EventRecord newRecord = new EventRecord(recordEntry); |
| 280 | addEventRecord(newRecord); |
| 281 | } |
| 282 | |
| 283 | EventRecord record = mCallEventRecordMap.get(recordEntry); |
| 284 | record.addEvent(event, currentSessionID, data); |
| 285 | } |
| 286 | } |
| 287 | |
| 288 | public void event(Loggable recordEntry, String event, String format, Object... args) { |
| 289 | String msg; |
| 290 | try { |
| 291 | msg = (args == null || args.length == 0) ? format |
| 292 | : String.format(Locale.US, format, args); |
| 293 | } catch (IllegalFormatException ife) { |
Brad Ebinger | ce97bfb | 2016-10-05 15:47:28 -0700 | [diff] [blame] | 294 | Log.e(this, ife, "IllegalFormatException: formatString='%s' numArgs=%d", format, |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 295 | args.length); |
| 296 | msg = format + " (An error occurred while formatting the message.)"; |
| 297 | } |
| 298 | |
| 299 | event(recordEntry, event, msg); |
| 300 | } |
| 301 | |
| 302 | public void dumpEvents(IndentingPrintWriter pw) { |
| 303 | pw.println("Historical Events:"); |
| 304 | pw.increaseIndent(); |
| 305 | for (EventRecord eventRecord : mEventRecords) { |
| 306 | eventRecord.dump(pw); |
| 307 | } |
| 308 | pw.decreaseIndent(); |
| 309 | } |
| 310 | |
| 311 | public void changeEventCacheSize(int newSize) { |
| 312 | |
| 313 | // Resize the event queue. |
| 314 | LinkedBlockingQueue<EventRecord> oldEventLog = mEventRecords; |
| 315 | mEventRecords = new LinkedBlockingQueue<>(newSize); |
| 316 | mCallEventRecordMap.clear(); |
| 317 | |
| 318 | oldEventLog.forEach((newRecord -> { |
| 319 | Loggable recordEntry = newRecord.getRecordEntry(); |
| 320 | // Copy the existing queue into the new one. |
| 321 | // First remove the oldest entry if no new ones exist. |
| 322 | if (mEventRecords.remainingCapacity() == 0) { |
| 323 | EventRecord record = mEventRecords.poll(); |
| 324 | if (record != null) { |
| 325 | mCallEventRecordMap.remove(record.getRecordEntry()); |
| 326 | } |
| 327 | } |
| 328 | |
| 329 | // Now add a new entry |
| 330 | mEventRecords.add(newRecord); |
| 331 | mCallEventRecordMap.put(recordEntry, newRecord); |
| 332 | |
| 333 | // Don't worry about notifying mEventListeners, since we are just resizing the records. |
| 334 | })); |
| 335 | } |
| 336 | |
| 337 | public void registerEventListener(EventListener e) { |
| 338 | if (e != null) { |
| 339 | synchronized (mSync) { |
| 340 | mEventListeners.add(e); |
| 341 | } |
| 342 | } |
| 343 | } |
| 344 | |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 345 | @VisibleForTesting |
| 346 | public LinkedBlockingQueue<EventRecord> getEventRecords() { |
| 347 | return mEventRecords; |
| 348 | } |
| 349 | |
| 350 | @VisibleForTesting |
| 351 | public Map<Loggable, EventRecord> getCallEventRecordMap() { |
| 352 | return mCallEventRecordMap; |
| 353 | } |
| 354 | |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 355 | private void addEventRecord(EventRecord newRecord) { |
| 356 | Loggable recordEntry = newRecord.getRecordEntry(); |
| 357 | |
| 358 | // First remove the oldest entry if no new ones exist. |
| 359 | if (mEventRecords.remainingCapacity() == 0) { |
| 360 | EventRecord record = mEventRecords.poll(); |
| 361 | if (record != null) { |
| 362 | mCallEventRecordMap.remove(record.getRecordEntry()); |
| 363 | } |
| 364 | } |
| 365 | |
| 366 | // Now add a new entry |
| 367 | mEventRecords.add(newRecord); |
| 368 | mCallEventRecordMap.put(recordEntry, newRecord); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 369 | synchronized (mSync) { |
| 370 | for (EventListener l : mEventListeners) { |
| 371 | l.eventRecordAdded(newRecord); |
| 372 | } |
| 373 | } |
| 374 | } |
| 375 | } |