| /* |
| * Copyright (C) 2016 The Android Open Source Project |
| * |
| * Licensed under the Apache License, Version 2.0 (the "License"); |
| * you may not use this file except in compliance with the License. |
| * You may obtain a copy of the License at |
| * |
| * http://www.apache.org/licenses/LICENSE-2.0 |
| * |
| * Unless required by applicable law or agreed to in writing, software |
| * distributed under the License is distributed on an "AS IS" BASIS, |
| * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| * See the License for the specific language governing permissions and |
| * limitations under the License |
| */ |
| |
| package android.telecom.Logging; |
| |
| import android.annotation.NonNull; |
| import android.telecom.Log; |
| import android.text.TextUtils; |
| import android.util.Pair; |
| |
| import com.android.internal.annotations.VisibleForTesting; |
| import com.android.internal.util.IndentingPrintWriter; |
| |
| import java.time.Instant; |
| import java.time.ZoneId; |
| import java.time.ZonedDateTime; |
| import java.time.format.DateTimeFormatter; |
| import java.util.ArrayList; |
| import java.util.Collections; |
| import java.util.Comparator; |
| import java.util.HashMap; |
| import java.util.IllegalFormatException; |
| import java.util.LinkedList; |
| import java.util.List; |
| import java.util.Locale; |
| import java.util.Map; |
| import java.util.concurrent.LinkedBlockingQueue; |
| |
| /** |
| * A utility class that provides the ability to define Events that a subsystem deems important, and |
| * then relate those events to other events so that information can be extracted. For example, a |
| * START and FINISH event can be defined and when a START and then FINISH occurs in a sequence, the |
| * time it took to complete that sequence can be saved to be retrieved later. |
| * @hide |
| */ |
| |
| public class EventManager { |
| |
| public static final String TAG = "Logging.Events"; |
| @VisibleForTesting |
| public static final int DEFAULT_EVENTS_TO_CACHE = 10; // Arbitrarily chosen. |
| public static final DateTimeFormatter DATE_TIME_FORMATTER = |
| DateTimeFormatter.ofPattern("HH:mm:ss.SSS"); |
| |
| public interface Loggable { |
| /** |
| * @return a unique String ID that will allow the Event to be recognized later in the logs. |
| */ |
| String getId(); |
| |
| /** |
| * @return Formatted information about the state that will be printed out later in the logs. |
| */ |
| String getDescription(); |
| } |
| |
| private final Map<Loggable, EventRecord> mCallEventRecordMap = new HashMap<>(); |
| private LinkedBlockingQueue<EventRecord> mEventRecords = |
| new LinkedBlockingQueue<>(DEFAULT_EVENTS_TO_CACHE); |
| |
| private List<EventListener> mEventListeners = new ArrayList<>(); |
| |
| public interface EventListener { |
| /** |
| * Notifies the implementation of this method that a new event record has been added. |
| * @param eventRecord Reference to the recently added EventRecord |
| */ |
| void eventRecordAdded(EventRecord eventRecord); |
| } |
| |
| private SessionManager.ISessionIdQueryHandler mSessionIdHandler; |
| /** |
| * Maps from request events to a list of possible response events. Used to track |
| * end-to-end timing for critical user-facing operations in Telecom. |
| */ |
| private final Map<String, List<TimedEventPair>> requestResponsePairs = new HashMap<>(); |
| |
| private static final Object mSync = new Object(); |
| |
| /** |
| * Stores the various events. |
| * Also stores all request-response pairs amongst the events. |
| */ |
| public static class TimedEventPair { |
| private static final long DEFAULT_TIMEOUT = 3000L; |
| |
| String mRequest; |
| String mResponse; |
| String mName; |
| long mTimeoutMillis = DEFAULT_TIMEOUT; |
| |
| public TimedEventPair(String request, String response, String name) { |
| this.mRequest = request; |
| this.mResponse = response; |
| this.mName = name; |
| } |
| |
| public TimedEventPair(String request, String response, String name, long timeoutMillis) { |
| this.mRequest = request; |
| this.mResponse = response; |
| this.mName = name; |
| this.mTimeoutMillis = timeoutMillis; |
| } |
| } |
| |
| public void addRequestResponsePair(TimedEventPair p) { |
| if (requestResponsePairs.containsKey(p.mRequest)) { |
| requestResponsePairs.get(p.mRequest).add(p); |
| } else { |
| ArrayList<TimedEventPair> responses = new ArrayList<>(); |
| responses.add(p); |
| requestResponsePairs.put(p.mRequest, responses); |
| } |
| } |
| |
| public static class Event { |
| public String eventId; |
| public String sessionId; |
| public long time; |
| public Object data; |
| // String storing the date for display. This will be computed at the time/timezone when |
| // the event is recorded. |
| public final String timestampString; |
| |
| public Event(String eventId, String sessionId, long time, Object data) { |
| this.eventId = eventId; |
| this.sessionId = sessionId; |
| this.time = time; |
| timestampString = |
| ZonedDateTime.ofInstant(Instant.ofEpochMilli(time), ZoneId.systemDefault()) |
| .format(DATE_TIME_FORMATTER); |
| this.data = data; |
| } |
| } |
| |
| public class EventRecord { |
| public class EventTiming extends TimedEvent<String> { |
| public String name; |
| public long time; |
| |
| public EventTiming(String name, long time) { |
| this.name = name; |
| this.time = time; |
| } |
| |
| public String getKey() { |
| return name; |
| } |
| |
| public long getTime() { |
| return time; |
| } |
| } |
| |
| private class PendingResponse { |
| String requestEventId; |
| long requestEventTimeMillis; |
| long timeoutMillis; |
| String name; |
| |
| public PendingResponse(String requestEventId, long requestEventTimeMillis, |
| long timeoutMillis, String name) { |
| this.requestEventId = requestEventId; |
| this.requestEventTimeMillis = requestEventTimeMillis; |
| this.timeoutMillis = timeoutMillis; |
| this.name = name; |
| } |
| } |
| |
| private final List<Event> mEvents = Collections.synchronizedList(new ArrayList<>()); |
| private final Loggable mRecordEntry; |
| |
| public EventRecord(Loggable recordEntry) { |
| mRecordEntry = recordEntry; |
| } |
| |
| public Loggable getRecordEntry() { |
| return mRecordEntry; |
| } |
| |
| public void addEvent(String event, String sessionId, Object data) { |
| mEvents.add(new Event(event, sessionId, System.currentTimeMillis(), data)); |
| Log.i("Event", "RecordEntry %s: %s, %s", mRecordEntry.getId(), event, data); |
| } |
| |
| public List<Event> getEvents() { |
| return new ArrayList<>(mEvents); |
| } |
| |
| public List<EventTiming> extractEventTimings() { |
| if (mEvents == null) { |
| return Collections.emptyList(); |
| } |
| |
| ArrayList<EventTiming> result = new ArrayList<>(); |
| Map<String, PendingResponse> pendingResponses = new HashMap<>(); |
| synchronized (mEvents) { |
| for (Event event : mEvents) { |
| if (requestResponsePairs.containsKey(event.eventId)) { |
| // This event expects a response, so add that expected response to the maps |
| // of pending events. |
| for (EventManager.TimedEventPair p : requestResponsePairs.get( |
| event.eventId)) { |
| pendingResponses.put(p.mResponse, new PendingResponse(event.eventId, |
| event.time, p.mTimeoutMillis, p.mName)); |
| } |
| } |
| |
| PendingResponse pendingResponse = pendingResponses.remove(event.eventId); |
| if (pendingResponse != null) { |
| long elapsedTime = event.time - pendingResponse.requestEventTimeMillis; |
| if (elapsedTime < pendingResponse.timeoutMillis) { |
| result.add(new EventTiming(pendingResponse.name, elapsedTime)); |
| } |
| } |
| } |
| } |
| |
| return result; |
| } |
| |
| public void dump(IndentingPrintWriter pw) { |
| pw.print(mRecordEntry.getDescription()); |
| |
| pw.increaseIndent(); |
| // Iterate over copy of events so that this doesn't hold the lock for too long. |
| for (Event event : getEvents()) { |
| pw.print(event.timestampString); |
| pw.print(" - "); |
| pw.print(event.eventId); |
| if (event.data != null) { |
| pw.print(" ("); |
| Object data = event.data; |
| |
| if (data instanceof Loggable) { |
| // If the data is another Loggable, then change the data to the |
| // Entry's Event ID instead. |
| EventRecord record = mCallEventRecordMap.get(data); |
| if (record != null) { |
| data = "RecordEntry " + record.mRecordEntry.getId(); |
| } |
| } |
| |
| pw.print(data); |
| pw.print(")"); |
| } |
| if (!TextUtils.isEmpty(event.sessionId)) { |
| pw.print(":"); |
| pw.print(event.sessionId); |
| } |
| pw.println(); |
| } |
| |
| pw.println("Timings (average for this call, milliseconds):"); |
| pw.increaseIndent(); |
| Map<String, Double> avgEventTimings = EventTiming.averageTimings(extractEventTimings()); |
| List<String> eventNames = new ArrayList<>(avgEventTimings.keySet()); |
| Collections.sort(eventNames); |
| for (String eventName : eventNames) { |
| pw.printf("%s: %.2f\n", eventName, avgEventTimings.get(eventName)); |
| } |
| pw.decreaseIndent(); |
| pw.decreaseIndent(); |
| } |
| } |
| |
| public EventManager(@NonNull SessionManager.ISessionIdQueryHandler l) { |
| mSessionIdHandler = l; |
| } |
| |
| public void event(Loggable recordEntry, String event, Object data) { |
| String currentSessionID = mSessionIdHandler.getSessionId(); |
| |
| if (recordEntry == null) { |
| Log.i(TAG, "Non-call EVENT: %s, %s", event, data); |
| return; |
| } |
| synchronized (mEventRecords) { |
| if (!mCallEventRecordMap.containsKey(recordEntry)) { |
| EventRecord newRecord = new EventRecord(recordEntry); |
| addEventRecord(newRecord); |
| } |
| |
| EventRecord record = mCallEventRecordMap.get(recordEntry); |
| record.addEvent(event, currentSessionID, data); |
| } |
| } |
| |
| public void event(Loggable recordEntry, String event, String format, Object... args) { |
| String msg; |
| try { |
| msg = (args == null || args.length == 0) ? format |
| : String.format(Locale.US, format, args); |
| } catch (IllegalFormatException ife) { |
| Log.e(this, ife, "IllegalFormatException: formatString='%s' numArgs=%d", format, |
| args.length); |
| msg = format + " (An error occurred while formatting the message.)"; |
| } |
| |
| event(recordEntry, event, msg); |
| } |
| |
| public void dumpEvents(IndentingPrintWriter pw) { |
| pw.println("Historical Events:"); |
| pw.increaseIndent(); |
| for (EventRecord eventRecord : mEventRecords) { |
| eventRecord.dump(pw); |
| } |
| pw.decreaseIndent(); |
| } |
| |
| /** |
| * Dumps events in a timeline format. |
| * @param pw The {@link IndentingPrintWriter} to output the timeline to. |
| * @hide |
| */ |
| public void dumpEventsTimeline(IndentingPrintWriter pw) { |
| pw.println("Historical Events (sorted by time):"); |
| |
| // Flatten event records out for sorting. |
| List<Pair<Loggable, Event>> events = new ArrayList<>(); |
| for (EventRecord er : mEventRecords) { |
| for (Event ev : er.getEvents()) { |
| events.add(new Pair<>(er.getRecordEntry(), ev)); |
| } |
| } |
| |
| // Sort by event time. This might result in out-of-order seeming events if the timezone |
| // changes somewhere in the middle. |
| Comparator<Pair<Loggable, Event>> byEventTime = |
| Comparator.comparingLong(e -> e.second.time); |
| events.sort(byEventTime); |
| |
| pw.increaseIndent(); |
| for (Pair<Loggable, Event> event : events) { |
| pw.print(event.second.timestampString); |
| pw.print(","); |
| pw.print(event.first.getId()); |
| pw.print(","); |
| pw.print(event.second.eventId); |
| pw.print(","); |
| pw.println(event.second.data); |
| } |
| pw.decreaseIndent(); |
| } |
| |
| public void changeEventCacheSize(int newSize) { |
| |
| // Resize the event queue. |
| LinkedBlockingQueue<EventRecord> oldEventLog = mEventRecords; |
| mEventRecords = new LinkedBlockingQueue<>(newSize); |
| mCallEventRecordMap.clear(); |
| |
| oldEventLog.forEach((newRecord -> { |
| Loggable recordEntry = newRecord.getRecordEntry(); |
| // Copy the existing queue into the new one. |
| // First remove the oldest entry if no new ones exist. |
| if (mEventRecords.remainingCapacity() == 0) { |
| EventRecord record = mEventRecords.poll(); |
| if (record != null) { |
| mCallEventRecordMap.remove(record.getRecordEntry()); |
| } |
| } |
| |
| // Now add a new entry |
| mEventRecords.add(newRecord); |
| mCallEventRecordMap.put(recordEntry, newRecord); |
| |
| // Don't worry about notifying mEventListeners, since we are just resizing the records. |
| })); |
| } |
| |
| public void registerEventListener(EventListener e) { |
| if (e != null) { |
| synchronized (mSync) { |
| mEventListeners.add(e); |
| } |
| } |
| } |
| |
| @VisibleForTesting |
| public LinkedBlockingQueue<EventRecord> getEventRecords() { |
| return mEventRecords; |
| } |
| |
| @VisibleForTesting |
| public Map<Loggable, EventRecord> getCallEventRecordMap() { |
| return mCallEventRecordMap; |
| } |
| |
| private void addEventRecord(EventRecord newRecord) { |
| Loggable recordEntry = newRecord.getRecordEntry(); |
| |
| // First remove the oldest entry if no new ones exist. |
| if (mEventRecords.remainingCapacity() == 0) { |
| EventRecord record = mEventRecords.poll(); |
| if (record != null) { |
| mCallEventRecordMap.remove(record.getRecordEntry()); |
| } |
| } |
| |
| // Now add a new entry |
| mEventRecords.add(newRecord); |
| mCallEventRecordMap.put(recordEntry, newRecord); |
| synchronized (mSync) { |
| for (EventListener l : mEventListeners) { |
| l.eventRecordAdded(newRecord); |
| } |
| } |
| } |
| } |