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