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.text.DateFormat; 28 import java.text.SimpleDateFormat; 29 import java.util.ArrayList; 30 import java.util.Collections; 31 import java.util.Comparator; 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.TimeZone; 40 import java.util.concurrent.LinkedBlockingQueue; 41 import java.util.stream.Collectors; 42 43 /** 44 * A utility class that provides the ability to define Events that a subsystem deems important, and 45 * then relate those events to other events so that information can be extracted. For example, a 46 * START and FINISH event can be defined and when a START and then FINISH occurs in a sequence, the 47 * time it took to complete that sequence can be saved to be retrieved later. 48 * @hide 49 */ 50 51 public class EventManager { 52 53 public static final String TAG = "Logging.Events"; 54 @VisibleForTesting 55 public static final int DEFAULT_EVENTS_TO_CACHE = 10; // Arbitrarily chosen. 56 private final DateFormat sDateFormat = new SimpleDateFormat("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 135 public Event(String eventId, String sessionId, long time, Object data) { 136 this.eventId = eventId; 137 this.sessionId = sessionId; 138 this.time = time; 139 this.data = data; 140 } 141 } 142 143 public class EventRecord { 144 public class EventTiming extends TimedEvent<String> { 145 public String name; 146 public long time; 147 148 public EventTiming(String name, long time) { 149 this.name = name; 150 this.time = time; 151 } 152 153 public String getKey() { 154 return name; 155 } 156 157 public long getTime() { 158 return time; 159 } 160 } 161 162 private class PendingResponse { 163 String requestEventId; 164 long requestEventTimeMillis; 165 long timeoutMillis; 166 String name; 167 168 public PendingResponse(String requestEventId, long requestEventTimeMillis, 169 long timeoutMillis, String name) { 170 this.requestEventId = requestEventId; 171 this.requestEventTimeMillis = requestEventTimeMillis; 172 this.timeoutMillis = timeoutMillis; 173 this.name = name; 174 } 175 } 176 177 private final List<Event> mEvents = new LinkedList<>(); 178 private final Loggable mRecordEntry; 179 180 public EventRecord(Loggable recordEntry) { 181 mRecordEntry = recordEntry; 182 } 183 184 public Loggable getRecordEntry() { 185 return mRecordEntry; 186 } 187 188 public void addEvent(String event, String sessionId, Object data) { 189 mEvents.add(new Event(event, sessionId, System.currentTimeMillis(), data)); 190 Log.i("Event", "RecordEntry %s: %s, %s", mRecordEntry.getId(), event, data); 191 } 192 193 public List<Event> getEvents() { 194 return mEvents; 195 } 196 197 public List<EventTiming> extractEventTimings() { 198 if (mEvents == null) { 199 return Collections.emptyList(); 200 } 201 202 LinkedList<EventTiming> result = new LinkedList<>(); 203 Map<String, PendingResponse> pendingResponses = new HashMap<>(); 204 for (Event event : mEvents) { 205 if (requestResponsePairs.containsKey(event.eventId)) { 206 // This event expects a response, so add that expected response to the maps 207 // of pending events. 208 for (EventManager.TimedEventPair p : requestResponsePairs.get(event.eventId)) { 209 pendingResponses.put(p.mResponse, new PendingResponse(event.eventId, 210 event.time, p.mTimeoutMillis, p.mName)); 211 } 212 } 213 214 PendingResponse pendingResponse = pendingResponses.remove(event.eventId); 215 if (pendingResponse != null) { 216 long elapsedTime = event.time - pendingResponse.requestEventTimeMillis; 217 if (elapsedTime < pendingResponse.timeoutMillis) { 218 result.add(new EventTiming(pendingResponse.name, elapsedTime)); 219 } 220 } 221 } 222 223 return result; 224 } 225 226 public void dump(IndentingPrintWriter pw) { 227 pw.print(mRecordEntry.getDescription()); 228 229 pw.increaseIndent(); 230 for (Event event : mEvents) { 231 pw.print(sDateFormat.format(new Date(event.time))); 232 pw.print(" - "); 233 pw.print(event.eventId); 234 if (event.data != null) { 235 pw.print(" ("); 236 Object data = event.data; 237 238 if (data instanceof Loggable) { 239 // If the data is another Loggable, then change the data to the 240 // Entry's Event ID instead. 241 EventRecord record = mCallEventRecordMap.get(data); 242 if (record != null) { 243 data = "RecordEntry " + record.mRecordEntry.getId(); 244 } 245 } 246 247 pw.print(data); 248 pw.print(")"); 249 } 250 if (!TextUtils.isEmpty(event.sessionId)) { 251 pw.print(":"); 252 pw.print(event.sessionId); 253 } 254 pw.println(); 255 } 256 257 pw.println("Timings (average for this call, milliseconds):"); 258 pw.increaseIndent(); 259 Map<String, Double> avgEventTimings = EventTiming.averageTimings(extractEventTimings()); 260 List<String> eventNames = new ArrayList<>(avgEventTimings.keySet()); 261 Collections.sort(eventNames); 262 for (String eventName : eventNames) { 263 pw.printf("%s: %.2f\n", eventName, avgEventTimings.get(eventName)); 264 } 265 pw.decreaseIndent(); 266 pw.decreaseIndent(); 267 } 268 } 269 270 public EventManager(@NonNull SessionManager.ISessionIdQueryHandler l) { 271 mSessionIdHandler = l; 272 sDateFormat.setTimeZone(TimeZone.getDefault()); 273 } 274 275 public void event(Loggable recordEntry, String event, Object data) { 276 String currentSessionID = mSessionIdHandler.getSessionId(); 277 278 if (recordEntry == null) { 279 Log.i(TAG, "Non-call EVENT: %s, %s", event, data); 280 return; 281 } 282 synchronized (mEventRecords) { 283 if (!mCallEventRecordMap.containsKey(recordEntry)) { 284 EventRecord newRecord = new EventRecord(recordEntry); 285 addEventRecord(newRecord); 286 } 287 288 EventRecord record = mCallEventRecordMap.get(recordEntry); 289 record.addEvent(event, currentSessionID, data); 290 } 291 } 292 293 public void event(Loggable recordEntry, String event, String format, Object... args) { 294 String msg; 295 try { 296 msg = (args == null || args.length == 0) ? format 297 : String.format(Locale.US, format, args); 298 } catch (IllegalFormatException ife) { 299 Log.e(this, ife, "IllegalFormatException: formatString='%s' numArgs=%d", format, 300 args.length); 301 msg = format + " (An error occurred while formatting the message.)"; 302 } 303 304 event(recordEntry, event, msg); 305 } 306 307 public void dumpEvents(IndentingPrintWriter pw) { 308 pw.println("Historical Events:"); 309 pw.increaseIndent(); 310 for (EventRecord eventRecord : mEventRecords) { 311 eventRecord.dump(pw); 312 } 313 pw.decreaseIndent(); 314 } 315 316 /** 317 * Dumps events in a timeline format. 318 * @param pw The {@link IndentingPrintWriter} to output the timeline to. 319 * @hide 320 */ 321 public void dumpEventsTimeline(IndentingPrintWriter pw) { 322 pw.println("Historical Events (sorted by time):"); 323 324 // Flatten event records out for sorting. 325 List<Pair<Loggable, Event>> events = new ArrayList<>(); 326 for (EventRecord er : mEventRecords) { 327 for (Event ev : er.getEvents()) { 328 events.add(new Pair<>(er.getRecordEntry(), ev)); 329 } 330 } 331 332 // Sort by event time. 333 Comparator<Pair<Loggable, Event>> byEventTime = (e1, e2) -> { 334 return Long.compare(e1.second.time, e2.second.time); 335 }; 336 events.sort(byEventTime); 337 338 pw.increaseIndent(); 339 for (Pair<Loggable, Event> event : events) { 340 pw.print(sDateFormat.format(new Date(event.second.time))); 341 pw.print(","); 342 pw.print(event.first.getId()); 343 pw.print(","); 344 pw.print(event.second.eventId); 345 pw.print(","); 346 pw.println(event.second.data); 347 } 348 pw.decreaseIndent(); 349 } 350 351 public void changeEventCacheSize(int newSize) { 352 353 // Resize the event queue. 354 LinkedBlockingQueue<EventRecord> oldEventLog = mEventRecords; 355 mEventRecords = new LinkedBlockingQueue<>(newSize); 356 mCallEventRecordMap.clear(); 357 358 oldEventLog.forEach((newRecord -> { 359 Loggable recordEntry = newRecord.getRecordEntry(); 360 // Copy the existing queue into the new one. 361 // First remove the oldest entry if no new ones exist. 362 if (mEventRecords.remainingCapacity() == 0) { 363 EventRecord record = mEventRecords.poll(); 364 if (record != null) { 365 mCallEventRecordMap.remove(record.getRecordEntry()); 366 } 367 } 368 369 // Now add a new entry 370 mEventRecords.add(newRecord); 371 mCallEventRecordMap.put(recordEntry, newRecord); 372 373 // Don't worry about notifying mEventListeners, since we are just resizing the records. 374 })); 375 } 376 377 public void registerEventListener(EventListener e) { 378 if (e != null) { 379 synchronized (mSync) { 380 mEventListeners.add(e); 381 } 382 } 383 } 384 385 @VisibleForTesting 386 public LinkedBlockingQueue<EventRecord> getEventRecords() { 387 return mEventRecords; 388 } 389 390 @VisibleForTesting 391 public Map<Loggable, EventRecord> getCallEventRecordMap() { 392 return mCallEventRecordMap; 393 } 394 395 private void addEventRecord(EventRecord newRecord) { 396 Loggable recordEntry = newRecord.getRecordEntry(); 397 398 // First remove the oldest entry if no new ones exist. 399 if (mEventRecords.remainingCapacity() == 0) { 400 EventRecord record = mEventRecords.poll(); 401 if (record != null) { 402 mCallEventRecordMap.remove(record.getRecordEntry()); 403 } 404 } 405 406 // Now add a new entry 407 mEventRecords.add(newRecord); 408 mCallEventRecordMap.put(recordEntry, newRecord); 409 synchronized (mSync) { 410 for (EventListener l : mEventListeners) { 411 l.eventRecordAdded(newRecord); 412 } 413 } 414 } 415 } 416