2db81b599b
Adding new event dump which shows the events for all call, sorted by time of event. Test: Manual Bug: 38450166 Change-Id: I9fd4ce92bdf62ef48d6940f03db1f2388003e9fc
414 lines
14 KiB
Java
414 lines
14 KiB
Java
/*
|
|
* 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.text.DateFormat;
|
|
import java.text.SimpleDateFormat;
|
|
import java.util.ArrayList;
|
|
import java.util.Collections;
|
|
import java.util.Comparator;
|
|
import java.util.Date;
|
|
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;
|
|
import java.util.stream.Collectors;
|
|
|
|
/**
|
|
* 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.
|
|
private final DateFormat sDateFormat = new SimpleDateFormat("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;
|
|
|
|
public Event(String eventId, String sessionId, long time, Object data) {
|
|
this.eventId = eventId;
|
|
this.sessionId = sessionId;
|
|
this.time = time;
|
|
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 = new LinkedList<>();
|
|
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 mEvents;
|
|
}
|
|
|
|
public List<EventTiming> extractEventTimings() {
|
|
if (mEvents == null) {
|
|
return Collections.emptyList();
|
|
}
|
|
|
|
LinkedList<EventTiming> result = new LinkedList<>();
|
|
Map<String, PendingResponse> pendingResponses = new HashMap<>();
|
|
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();
|
|
for (Event event : mEvents) {
|
|
pw.print(sDateFormat.format(new Date(event.time)));
|
|
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.
|
|
Comparator<Pair<Loggable, Event>> byEventTime = (e1, e2) -> {
|
|
return Long.compare(e1.second.time, e2.second.time);
|
|
};
|
|
events.sort(byEventTime);
|
|
|
|
pw.increaseIndent();
|
|
for (Pair<Loggable, Event> event : events) {
|
|
pw.print(sDateFormat.format(new Date(event.second.time)));
|
|
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);
|
|
}
|
|
}
|
|
}
|
|
}
|