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